"./sync.test -test.v -test.timeout 1h0m0s -remote TestCompressDrive: -verbose" - Starting (try 1/5) 2022/03/02 05:30:09 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7" 2022/03/02 05:30:09 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/03/02 05:30:10 DEBUG : Creating backend with remote "/tmp/rclone197051821" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.03s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:11 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2022/03/02 05:30:11 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:11 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish --- PASS: TestCopyWithDryRun (2.04s) === RUN TestCopy run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:12 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:12 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:30:17 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:30:17 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:30:21 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/02 05:30:21 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestCopy (9.58s) === RUN TestCopyMissingDirectory run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:22 DEBUG : Creating backend with remote "/non-existing" 2022/03/02 05:30:22 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2022/03/02 05:30:22 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:22 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.80s) === RUN TestCopyNoTraverse run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:23 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:23 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:30:27 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:30:27 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:30:31 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/02 05:30:31 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestCopyNoTraverse (9.38s) === RUN TestCopyCheckFirst run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:32 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Running all checks before starting transfers 2022/03/02 05:30:32 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:32 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Checks finished, now starting transfers 2022/03/02 05:30:32 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:30:37 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:30:37 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:30:40 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:30:40 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopyCheckFirst (9.43s) === RUN TestSyncNoTraverse run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:41 ERROR : Ignoring --no-traverse with sync 2022/03/02 05:30:42 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:42 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:30:46 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:30:46 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:30:46 DEBUG : Waiting for deletions to finish 2022/03/02 05:30:50 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/02 05:30:50 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestSyncNoTraverse (9.86s) === RUN TestCopyWithDepth run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:51 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:51 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:30:55 DEBUG : hello world2: md5 = cc2c857f89648dbd139d7b2a6665957d OK 2022/03/02 05:30:55 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (7.53s) === RUN TestCopyWithFilesFrom run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:30:59 DEBUG : hello world2: Excluded 2022/03/02 05:30:59 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:30:59 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:31:03 DEBUG : potato2: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:31:03 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (7.15s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:31:06 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:31:06 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:31:09 DEBUG : potato2: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:31:09 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (6.96s) === RUN TestCopyEmptyDirectories run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:31:13 DEBUG : sub dir2: Making directory 2022/03/02 05:31:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:31:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:31:17 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:31:17 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:31:17 DEBUG : sub dir2: Making directory 2022/03/02 05:31:18 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: copied 1 directories 2022/03/02 05:31:23 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:31:23 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopyEmptyDirectories (11.41s) === RUN TestMoveEmptyDirectories run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:31:24 DEBUG : sub dir2: Making directory 2022/03/02 05:31:25 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:31:25 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:31:29 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:31:29 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:31:29 INFO : sub dir/hello world: Deleted 2022/03/02 05:31:29 DEBUG : sub dir: Making directory 2022/03/02 05:31:29 DEBUG : sub dir2: Making directory 2022/03/02 05:31:30 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: copied 2 directories 2022/03/02 05:31:35 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:31:35 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestMoveEmptyDirectories (11.79s) === RUN TestSyncEmptyDirectories run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:31:36 DEBUG : sub dir2: Making directory 2022/03/02 05:31:36 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:31:36 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:31:40 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:31:40 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:31:40 DEBUG : sub dir2: Making directory 2022/03/02 05:31:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: copied 1 directories 2022/03/02 05:31:41 DEBUG : Waiting for deletions to finish 2022/03/02 05:31:47 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:31:47 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestSyncEmptyDirectories (11.61s) === RUN TestServerSideCopy run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:31:54 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-cewasin9famejow5tubiloc7" 2022/03/02 05:31:54 DEBUG : Config file has changed externaly - reloading sync_test.go:275: Server side copy (if possible) Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7 -> Compressed: TestCompressDrive:rclone-test-cewasin9famejow5tubiloc7 2022/03/02 05:31:56 DEBUG : Compressed: TestCompressDrive:rclone-test-cewasin9famejow5tubiloc7: Waiting for checks to finish 2022/03/02 05:31:56 DEBUG : Compressed: TestCompressDrive:rclone-test-cewasin9famejow5tubiloc7: Waiting for transfers to finish 2022/03/02 05:32:01 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:32:01 INFO : sub dir/hello world: Copied (server-side copy) 2022/03/02 05:32:03 DEBUG : Compressed: TestCompressDrive:rclone-test-cewasin9famejow5tubiloc7: Purge remote 2022/03/02 05:32:06 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:32:06 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestServerSideCopy (19.10s) === RUN TestCopyAfterDelete run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:32:11 ERROR : : error listing: directory not found 2022/03/02 05:32:13 DEBUG : Local file system at /tmp/rclone197051821: Making directory 2022/03/02 05:32:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:17 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:32:17 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopyAfterDelete (11.13s) === RUN TestCopyRedownload run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:32:25 DEBUG : Local file system at /tmp/rclone197051821: Waiting for checks to finish 2022/03/02 05:32:25 DEBUG : Local file system at /tmp/rclone197051821: Waiting for transfers to finish 2022/03/02 05:32:26 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:32:26 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:32:28 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/02 05:32:28 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestCopyRedownload (11.45s) === RUN TestSyncBasedOnCheckSum run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:32:30 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:30 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:33 DEBUG : check sum: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/02 05:32:33 INFO : check sum: Copied (new) 2022/03/02 05:32:33 DEBUG : Waiting for deletions to finish 2022/03/02 05:32:35 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:36 DEBUG : check sum: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/02 05:32:36 DEBUG : check sum: Size and md5 of src and dst objects identical 2022/03/02 05:32:36 DEBUG : check sum: Unchanged skipping 2022/03/02 05:32:36 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:36 DEBUG : Waiting for deletions to finish 2022/03/02 05:32:36 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (9.95s) === RUN TestSyncSizeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:32:40 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:40 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:43 DEBUG : sizeonly: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/02 05:32:43 INFO : sizeonly: Copied (new) 2022/03/02 05:32:43 DEBUG : Waiting for deletions to finish 2022/03/02 05:32:45 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:45 DEBUG : sizeonly: Sizes identical 2022/03/02 05:32:45 DEBUG : sizeonly: Unchanged skipping 2022/03/02 05:32:45 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:45 DEBUG : Waiting for deletions to finish 2022/03/02 05:32:45 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (8.90s) === RUN TestSyncIgnoreSize run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:32:49 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:49 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:52 DEBUG : ignore-size: md5 = 98bf7d8c15784f0a3d63204441e1e2aa OK 2022/03/02 05:32:52 INFO : ignore-size: Copied (new) 2022/03/02 05:32:52 DEBUG : Waiting for deletions to finish 2022/03/02 05:32:54 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:32:54 DEBUG : ignore-size: Unchanged skipping 2022/03/02 05:32:54 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:32:54 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:32:54 DEBUG : Waiting for deletions to finish 2022/03/02 05:32:54 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (9.22s) === RUN TestSyncIgnoreTimes run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:33:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:03 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:33:03 DEBUG : existing: Unchanged skipping 2022/03/02 05:33:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:33:03 DEBUG : Waiting for deletions to finish 2022/03/02 05:33:03 INFO : There was nothing to transfer 2022/03/02 05:33:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:03 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2022/03/02 05:33:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:33:07 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/02 05:33:07 INFO : existing: Copied (replaced existing) 2022/03/02 05:33:07 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (12.51s) === RUN TestSyncIgnoreExisting run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:33:10 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:10 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:33:14 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/02 05:33:14 INFO : existing: Copied (new) 2022/03/02 05:33:14 DEBUG : Waiting for deletions to finish 2022/03/02 05:33:15 DEBUG : existing: Destination exists, skipping 2022/03/02 05:33:15 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:15 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:33:15 DEBUG : Waiting for deletions to finish 2022/03/02 05:33:15 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (8.92s) === RUN TestSyncIgnoreErrors run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:33:27 DEBUG : d: Making directory 2022/03/02 05:33:32 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:33:32 DEBUG : c/non empty space: Unchanged skipping 2022/03/02 05:33:32 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:32 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:33:32 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:33:32 DEBUG : pacer: Rate limited, increasing sleep to 1.936266125s 2022/03/02 05:33:33 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:33:38 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:33:38 INFO : a/potato2: Copied (new) 2022/03/02 05:33:38 DEBUG : Waiting for deletions to finish 2022/03/02 05:33:39 INFO : b/potato: Deleted 2022/03/02 05:33:39 INFO : d: Removing directory 2022/03/02 05:33:40 INFO : b: Removing directory 2022/03/02 05:33:41 DEBUG : b: Rmdir: contains trashed file: "potato.json" 2022/03/02 05:33:41 DEBUG : b: Rmdir: contains trashed file: "potato.FQAAAAAAAAA.gz" 2022/03/02 05:33:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: deleted 2 directories 2022/03/02 05:33:48 DEBUG : c: Rmdir: contains trashed file: "non empty space.json" 2022/03/02 05:33:48 DEBUG : c: Rmdir: contains trashed file: "non empty space.bin" 2022/03/02 05:33:49 DEBUG : a: Rmdir: contains trashed file: "potato2.json" 2022/03/02 05:33:49 DEBUG : a: Rmdir: contains trashed file: "potato2.PAAAAAAAAAA.gz" --- PASS: TestSyncIgnoreErrors (31.19s) === RUN TestSyncAfterChangingModtimeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:33:56 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/02 05:33:56 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:57 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/02 05:33:57 NOTICE: empty space: Skipped update modification time as --dry-run is set (size 1) 2022/03/02 05:33:57 DEBUG : empty space: Unchanged skipping 2022/03/02 05:33:57 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:33:57 DEBUG : Waiting for deletions to finish 2022/03/02 05:33:57 INFO : There was nothing to transfer 2022/03/02 05:33:59 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:33:59 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/02 05:33:59 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/02 05:34:00 INFO : empty space: Updated modification time in destination 2022/03/02 05:34:00 DEBUG : empty space: Unchanged skipping 2022/03/02 05:34:00 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:34:00 DEBUG : Waiting for deletions to finish 2022/03/02 05:34:00 INFO : There was nothing to transfer --- PASS: TestSyncAfterChangingModtimeOnly (13.36s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:34:09 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:34:09 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/02 05:34:10 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/02 05:34:10 DEBUG : empty space: Unchanged skipping 2022/03/02 05:34:10 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:34:10 DEBUG : Waiting for deletions to finish 2022/03/02 05:34:10 INFO : There was nothing to transfer --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (10.08s) === RUN TestSyncDoesntUpdateModtime run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:34:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:34:19 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/02 05:34:20 DEBUG : foo: md5 = acbd18db4cc2f85cedef654fccc4a4d8 (Local file system at /tmp/rclone197051821) 2022/03/02 05:34:20 DEBUG : foo: md5 = 37b51d194a7513e45b56f6524f2d51f2 (Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7) 2022/03/02 05:34:20 DEBUG : foo: md5 differ 2022/03/02 05:34:20 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:34:22 DEBUG : foo: md5 = acbd18db4cc2f85cedef654fccc4a4d8 OK 2022/03/02 05:34:22 INFO : foo: Copied (replaced existing) 2022/03/02 05:34:22 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (12.45s) === RUN TestSyncAfterAddingAFile run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:34:31 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:34:31 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:34:31 DEBUG : empty space: Unchanged skipping 2022/03/02 05:34:31 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:34:34 DEBUG : potato: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:34:34 INFO : potato: Copied (new) 2022/03/02 05:34:34 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (14.71s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:34:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:34:46 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2022/03/02 05:34:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:34:50 DEBUG : potato: md5 = 100defcf18c42a1e0dc42a789b107cd2 OK 2022/03/02 05:34:50 INFO : potato: Copied (replaced existing) 2022/03/02 05:34:50 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (13.06s) === RUN TestSyncAfterChangingContentsOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:34:59 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2022/03/02 05:34:59 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:35:00 DEBUG : potato: md5 = e4cb6955d9106df6263c45fcfc10f163 (Local file system at /tmp/rclone197051821) 2022/03/02 05:35:00 DEBUG : potato: md5 = 100defcf18c42a1e0dc42a789b107cd2 (Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7) 2022/03/02 05:35:00 DEBUG : potato: md5 differ 2022/03/02 05:35:00 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:35:03 DEBUG : potato: md5 = e4cb6955d9106df6263c45fcfc10f163 OK 2022/03/02 05:35:03 INFO : potato: Copied (replaced existing) 2022/03/02 05:35:03 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (12.52s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:35:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:35:13 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:35:13 DEBUG : empty space: Unchanged skipping 2022/03/02 05:35:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:35:13 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2022/03/02 05:35:13 DEBUG : Waiting for deletions to finish 2022/03/02 05:35:13 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (12.99s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:35:28 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:35:28 DEBUG : empty space: Unchanged skipping 2022/03/02 05:35:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:35:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:35:32 DEBUG : potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:35:32 INFO : potato2: Copied (new) 2022/03/02 05:35:32 DEBUG : Waiting for deletions to finish 2022/03/02 05:35:33 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (19.89s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:35:48 DEBUG : d: Making directory 2022/03/02 05:35:49 DEBUG : d/e: Making directory 2022/03/02 05:35:53 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:35:53 DEBUG : c/non empty space: Unchanged skipping 2022/03/02 05:35:55 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:35:55 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:35:57 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:35:57 INFO : a/potato2: Copied (new) 2022/03/02 05:35:57 DEBUG : Waiting for deletions to finish 2022/03/02 05:35:59 INFO : b/potato: Deleted 2022/03/02 05:35:59 INFO : d/e: Removing directory 2022/03/02 05:36:00 INFO : d: Removing directory 2022/03/02 05:36:00 DEBUG : d: Rmdir: contains trashed file: "e" 2022/03/02 05:36:01 INFO : b: Removing directory 2022/03/02 05:36:01 DEBUG : b: Rmdir: contains trashed file: "potato.FQAAAAAAAAA.gz" 2022/03/02 05:36:01 DEBUG : b: Rmdir: contains trashed file: "potato.json" 2022/03/02 05:36:02 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: deleted 3 directories 2022/03/02 05:36:08 DEBUG : c: Rmdir: contains trashed file: "non empty space.json" 2022/03/02 05:36:08 DEBUG : c: Rmdir: contains trashed file: "non empty space.bin" 2022/03/02 05:36:09 DEBUG : a: Rmdir: contains trashed file: "potato2.json" 2022/03/02 05:36:09 DEBUG : a: Rmdir: contains trashed file: "potato2.PAAAAAAAAAA.gz" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (31.10s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:36:19 DEBUG : d: Making directory 2022/03/02 05:36:23 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:36:23 DEBUG : c/non empty space: Unchanged skipping 2022/03/02 05:36:23 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:36:23 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:36:27 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:36:27 INFO : a/potato2: Copied (new) 2022/03/02 05:36:27 ERROR : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: not deleting files as there were IO errors 2022/03/02 05:36:27 ERROR : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: not deleting directories as there were IO errors 2022/03/02 05:36:37 DEBUG : c: Rmdir: contains trashed file: "non empty space.json" 2022/03/02 05:36:37 DEBUG : c: Rmdir: contains trashed file: "non empty space.bin" 2022/03/02 05:36:38 DEBUG : b: Rmdir: contains trashed file: "potato.json" 2022/03/02 05:36:38 DEBUG : b: Rmdir: contains trashed file: "potato.FQAAAAAAAAA.gz" 2022/03/02 05:36:39 DEBUG : a: Rmdir: contains trashed file: "potato2.PAAAAAAAAAA.gz" 2022/03/02 05:36:39 DEBUG : a: Rmdir: contains trashed file: "potato2.json" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (30.05s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:36:49 DEBUG : Waiting for deletions to finish 2022/03/02 05:36:50 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:36:50 DEBUG : empty space: Unchanged skipping 2022/03/02 05:36:50 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:36:50 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:36:51 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:36:51 DEBUG : pacer: Rate limited, increasing sleep to 1.661105425s 2022/03/02 05:36:51 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:36:51 INFO : potato: Deleted 2022/03/02 05:36:54 DEBUG : potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:36:54 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (19.47s) === RUN TestSyncDeleteBefore run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:37:09 DEBUG : Waiting for deletions to finish 2022/03/02 05:37:09 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:37:09 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:37:11 INFO : potato: Deleted 2022/03/02 05:37:11 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:37:11 DEBUG : empty space: Unchanged skipping 2022/03/02 05:37:11 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:37:11 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:37:14 DEBUG : potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/02 05:37:14 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (20.49s) === RUN TestCopyDeleteBefore run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:37:25 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:37:25 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:37:29 DEBUG : potato2: md5 = 9519bc2e940e1696ea7365b4b81adedc OK 2022/03/02 05:37:29 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (14.88s) === RUN TestSyncWithExclude run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:37:44 DEBUG : enormous: Excluded 2022/03/02 05:37:44 DEBUG : potato2: Excluded 2022/03/02 05:37:45 DEBUG : potato2: Excluded 2022/03/02 05:37:45 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:37:45 DEBUG : empty space: Unchanged skipping 2022/03/02 05:37:45 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:37:45 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:37:45 DEBUG : Waiting for deletions to finish 2022/03/02 05:37:45 INFO : There was nothing to transfer 2022/03/02 05:37:47 DEBUG : enormous: Excluded 2022/03/02 05:37:47 DEBUG : potato2: Excluded 2022/03/02 05:37:47 DEBUG : potato2: Excluded 2022/03/02 05:37:47 DEBUG : Local file system at /tmp/rclone197051821: Waiting for checks to finish 2022/03/02 05:37:47 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/02 05:37:47 DEBUG : empty space: Unchanged skipping 2022/03/02 05:37:47 DEBUG : Local file system at /tmp/rclone197051821: Waiting for transfers to finish 2022/03/02 05:37:47 DEBUG : Waiting for deletions to finish 2022/03/02 05:37:47 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (15.86s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:38:05 DEBUG : enormous: Excluded 2022/03/02 05:38:05 DEBUG : potato2: Excluded 2022/03/02 05:38:05 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:38:05 DEBUG : empty space: Unchanged skipping 2022/03/02 05:38:05 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:38:05 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:38:05 DEBUG : Waiting for deletions to finish 2022/03/02 05:38:06 INFO : enormous: Deleted 2022/03/02 05:38:06 INFO : potato2: Deleted 2022/03/02 05:38:06 INFO : There was nothing to transfer 2022/03/02 05:38:08 DEBUG : Local file system at /tmp/rclone197051821: Waiting for checks to finish 2022/03/02 05:38:08 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/02 05:38:08 DEBUG : empty space: Unchanged skipping 2022/03/02 05:38:08 DEBUG : Local file system at /tmp/rclone197051821: Waiting for transfers to finish 2022/03/02 05:38:08 DEBUG : Waiting for deletions to finish 2022/03/02 05:38:08 INFO : enormous: Deleted 2022/03/02 05:38:08 INFO : potato2: Deleted 2022/03/02 05:38:08 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (19.34s) === RUN TestSyncWithUpdateOlder run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:38:29 DEBUG : four: Sizes differ (src 4 vs dst 8) 2022/03/02 05:38:29 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2022/03/02 05:38:29 DEBUG : one: Destination is newer than source, skipping 2022/03/02 05:38:29 DEBUG : three: Sizes identical 2022/03/02 05:38:29 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2022/03/02 05:38:29 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:38:31 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 (Local file system at /tmp/rclone197051821) 2022/03/02 05:38:31 DEBUG : two: md5 = 0f82d86afa0f5dc965c5c15aca58dcfb (Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7) 2022/03/02 05:38:31 DEBUG : two: md5 differ 2022/03/02 05:38:31 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:38:33 DEBUG : five: md5 = 30056e1cab7a61d256fc8edd970d14f5 OK 2022/03/02 05:38:33 INFO : five: Copied (new) 2022/03/02 05:38:33 DEBUG : four: md5 = 8cbad96aced40b3838dd9f07f6ef5772 OK 2022/03/02 05:38:33 INFO : four: Copied (replaced existing) 2022/03/02 05:38:33 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/02 05:38:33 INFO : two: Copied (replaced existing) 2022/03/02 05:38:33 DEBUG : Waiting for deletions to finish 2022/03/02 05:38:40 DEBUG : one: Destination is newer than source, skipping 2022/03/02 05:38:40 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:38:41 DEBUG : three: md5 = 35d6d33467aae9a2e3dccb4b6b027878 (Local file system at /tmp/rclone197051821) 2022/03/02 05:38:41 DEBUG : three: md5 = 413af0de1f97a2155acf2b8b26ab36e2 (Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7) 2022/03/02 05:38:41 DEBUG : three: md5 differ 2022/03/02 05:38:41 DEBUG : three: Destination mod time is within 1s of source but files differ, transferring 2022/03/02 05:38:41 DEBUG : five: md5 = 30056e1cab7a61d256fc8edd970d14f5 OK 2022/03/02 05:38:41 DEBUG : five: Size and md5 of src and dst objects identical 2022/03/02 05:38:41 DEBUG : five: Destination mod time is within 1s of source and files identical, skipping 2022/03/02 05:38:41 DEBUG : four: md5 = 8cbad96aced40b3838dd9f07f6ef5772 OK 2022/03/02 05:38:41 DEBUG : four: Size and md5 of src and dst objects identical 2022/03/02 05:38:41 DEBUG : four: Destination mod time is within 1s of source and files identical, skipping 2022/03/02 05:38:41 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/02 05:38:41 DEBUG : two: Size and md5 of src and dst objects identical 2022/03/02 05:38:41 DEBUG : two: Destination mod time is within 1s of source and files identical, skipping 2022/03/02 05:38:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:38:43 DEBUG : three: md5 = 35d6d33467aae9a2e3dccb4b6b027878 OK 2022/03/02 05:38:43 INFO : three: Copied (replaced existing) 2022/03/02 05:38:43 DEBUG : Waiting for deletions to finish --- PASS: TestSyncWithUpdateOlder (46.40s) === RUN TestSyncWithMaxDuration sync_test.go:1009: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1058: Can track renames: true 2022/03/02 05:38:57 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Making map for --track-renames 2022/03/02 05:38:57 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Finished making map for --track-renames 2022/03/02 05:38:57 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:38:57 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for renames to finish 2022/03/02 05:38:57 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:00 DEBUG : yam: md5 = 48dc443644c4b89556dc06834b46451d OK 2022/03/02 05:39:00 INFO : yam: Copied (new) 2022/03/02 05:39:01 DEBUG : potato: md5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2022/03/02 05:39:01 INFO : potato: Copied (new) 2022/03/02 05:39:01 DEBUG : Waiting for deletions to finish 2022/03/02 05:39:04 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:39:04 DEBUG : potato: Unchanged skipping 2022/03/02 05:39:04 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Making map for --track-renames 2022/03/02 05:39:05 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Finished making map for --track-renames 2022/03/02 05:39:05 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:39:05 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for renames to finish 2022/03/02 05:39:07 INFO : yam: Moved (server-side) to: yaml 2022/03/02 05:39:07 INFO : yaml: Renamed from "yam" 2022/03/02 05:39:07 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:07 DEBUG : Waiting for deletions to finish 2022/03/02 05:39:07 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenames (15.60s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1127: Can track renames: true 2022/03/02 05:39:13 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Making map for --track-renames 2022/03/02 05:39:13 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Finished making map for --track-renames 2022/03/02 05:39:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:39:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for renames to finish 2022/03/02 05:39:13 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:16 DEBUG : yam: md5 = 48dc443644c4b89556dc06834b46451d OK 2022/03/02 05:39:16 INFO : yam: Copied (new) 2022/03/02 05:39:16 DEBUG : potato: md5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2022/03/02 05:39:16 INFO : potato: Copied (new) 2022/03/02 05:39:16 DEBUG : Waiting for deletions to finish 2022/03/02 05:39:19 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:39:19 DEBUG : potato: Unchanged skipping 2022/03/02 05:39:19 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Making map for --track-renames 2022/03/02 05:39:19 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Finished making map for --track-renames 2022/03/02 05:39:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:39:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for renames to finish 2022/03/02 05:39:22 INFO : yam: Moved (server-side) to: yaml 2022/03/02 05:39:22 INFO : yaml: Renamed from "yam" 2022/03/02 05:39:22 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:22 DEBUG : Waiting for deletions to finish 2022/03/02 05:39:22 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyModtime (15.06s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1163: Can track renames: true 2022/03/02 05:39:28 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Making map for --track-renames 2022/03/02 05:39:28 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Finished making map for --track-renames 2022/03/02 05:39:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:39:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for renames to finish 2022/03/02 05:39:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:32 DEBUG : sub/yam: md5 = 48dc443644c4b89556dc06834b46451d OK 2022/03/02 05:39:32 INFO : sub/yam: Copied (new) 2022/03/02 05:39:32 DEBUG : potato: md5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2022/03/02 05:39:32 INFO : potato: Copied (new) 2022/03/02 05:39:32 DEBUG : Waiting for deletions to finish 2022/03/02 05:39:35 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:39:35 DEBUG : potato: Unchanged skipping 2022/03/02 05:39:36 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Making map for --track-renames 2022/03/02 05:39:36 INFO : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Finished making map for --track-renames 2022/03/02 05:39:36 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:39:36 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for renames to finish 2022/03/02 05:39:39 INFO : sub/yam: Moved (server-side) to: yam 2022/03/02 05:39:39 INFO : yam: Renamed from "sub/yam" 2022/03/02 05:39:39 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:39 DEBUG : Waiting for deletions to finish 2022/03/02 05:39:39 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (18.33s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:39:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:39:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:39:51 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:39:51 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:39:51 INFO : sub dir/hello world: Deleted 2022/03/02 05:39:53 DEBUG : nested/sub dir/file: md5 = 83d3784ea62518eafc60e98d84f877ad OK 2022/03/02 05:39:53 INFO : nested/sub dir/file: Copied (new) 2022/03/02 05:39:53 INFO : nested/sub dir/file: Deleted 2022/03/02 05:39:53 INFO : sub dir: Removing directory 2022/03/02 05:39:53 INFO : nested/sub dir: Removing directory 2022/03/02 05:39:53 INFO : nested: Removing directory 2022/03/02 05:39:53 DEBUG : Local file system at /tmp/rclone197051821: deleted 3 directories 2022/03/02 05:40:00 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:40:00 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/02 05:40:01 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.json" 2022/03/02 05:40:01 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.bin" 2022/03/02 05:40:02 DEBUG : nested: Rmdir: contains trashed file: "sub dir" --- PASS: TestMoveWithDeleteEmptySrcDirs (16.73s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:40:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:40:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:40:08 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/02 05:40:08 INFO : sub dir/hello world: Copied (new) 2022/03/02 05:40:08 INFO : sub dir/hello world: Deleted 2022/03/02 05:40:09 DEBUG : nested/sub dir/file: md5 = 83d3784ea62518eafc60e98d84f877ad OK 2022/03/02 05:40:09 INFO : nested/sub dir/file: Copied (new) 2022/03/02 05:40:09 INFO : nested/sub dir/file: Deleted 2022/03/02 05:40:16 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/02 05:40:16 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/02 05:40:17 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.bin" 2022/03/02 05:40:17 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.json" 2022/03/02 05:40:18 DEBUG : nested: Rmdir: contains trashed file: "sub dir" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (15.97s) === RUN TestMoveWithIgnoreExisting run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:40:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:40:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:40:22 DEBUG : existing-b: md5 = 006f87892f47ef9aa60fa5ed01a440fb OK 2022/03/02 05:40:22 INFO : existing-b: Copied (new) 2022/03/02 05:40:22 INFO : existing-b: Deleted 2022/03/02 05:40:22 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/02 05:40:22 INFO : existing: Copied (new) 2022/03/02 05:40:22 INFO : existing: Deleted 2022/03/02 05:40:25 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:40:25 DEBUG : existing: Destination exists, skipping 2022/03/02 05:40:25 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2022/03/02 05:40:25 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:40:25 INFO : There was nothing to transfer --- PASS: TestMoveWithIgnoreExisting (12.76s) === RUN TestServerSideMove run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:40:31 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9" sync_test.go:1215: Server side move (if possible) Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7 -> Compressed: TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9 2022/03/02 05:40:55 DEBUG : Compressed: TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9: Using server-side directory move 2022/03/02 05:40:55 INFO : Compressed: TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/02 05:40:56 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/02 05:40:56 DEBUG : empty space: Unchanged skipping 2022/03/02 05:40:56 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/02 05:40:56 DEBUG : Compressed: TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9: Waiting for checks to finish 2022/03/02 05:40:57 INFO : empty space: Deleted 2022/03/02 05:40:57 DEBUG : Compressed: TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9: Waiting for transfers to finish 2022/03/02 05:40:57 INFO : potato3: Deleted 2022/03/02 05:40:59 INFO : potato2: Moved (server-side) 2022/03/02 05:41:00 INFO : potato3: Moved (server-side) 2022/03/02 05:41:00 INFO : There was nothing to transfer 2022/03/02 05:41:04 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-jelipub5mesikih0gosozup3" 2022/03/02 05:41:05 DEBUG : Compressed: TestCompressDrive:rclone-test-jelipub5mesikih0gosozup3: Using server-side directory move 2022/03/02 05:41:06 INFO : Compressed: TestCompressDrive:rclone-test-jelipub5mesikih0gosozup3: Server side directory move succeeded 2022/03/02 05:41:10 DEBUG : Compressed: TestCompressDrive:rclone-test-jelipub5mesikih0gosozup3: Purge remote 2022/03/02 05:41:11 DEBUG : Compressed: TestCompressDrive:rclone-test-nulowar3yuhitog3nopipil9: Purge remote 2022/03/02 05:41:11 purge failed: directory not found --- PASS: TestServerSideMove (40.10s) === RUN TestServerSideMoveWithFilter run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:41:11 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-jidirot7jalocus8belaguy3" sync_test.go:1215: Server side move (if possible) Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7 -> Compressed: TestCompressDrive:rclone-test-jidirot7jalocus8belaguy3 2022/03/02 05:41:36 DEBUG : empty space: Excluded 2022/03/02 05:41:36 DEBUG : empty space: Excluded 2022/03/02 05:41:36 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/02 05:41:36 DEBUG : Compressed: TestCompressDrive:rclone-test-jidirot7jalocus8belaguy3: Waiting for checks to finish 2022/03/02 05:41:36 DEBUG : Compressed: TestCompressDrive:rclone-test-jidirot7jalocus8belaguy3: Waiting for transfers to finish 2022/03/02 05:41:38 INFO : potato3: Deleted 2022/03/02 05:41:39 INFO : potato2: Moved (server-side) 2022/03/02 05:41:41 INFO : potato3: Moved (server-side) 2022/03/02 05:41:41 INFO : There was nothing to transfer 2022/03/02 05:41:45 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-jixacev9ruhunek3gepazuv5" 2022/03/02 05:41:46 DEBUG : empty space: Excluded 2022/03/02 05:41:46 DEBUG : Compressed: TestCompressDrive:rclone-test-jixacev9ruhunek3gepazuv5: Waiting for checks to finish 2022/03/02 05:41:46 DEBUG : Compressed: TestCompressDrive:rclone-test-jixacev9ruhunek3gepazuv5: Waiting for transfers to finish 2022/03/02 05:41:49 INFO : potato3: Moved (server-side) 2022/03/02 05:41:50 INFO : potato2: Moved (server-side) 2022/03/02 05:41:50 INFO : There was nothing to transfer 2022/03/02 05:41:53 DEBUG : Compressed: TestCompressDrive:rclone-test-jixacev9ruhunek3gepazuv5: Purge remote 2022/03/02 05:41:53 DEBUG : Compressed: TestCompressDrive:rclone-test-jidirot7jalocus8belaguy3: Purge remote --- PASS: TestServerSideMoveWithFilter (44.78s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:41:56 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4" 2022/03/02 05:42:07 DEBUG : tomatoDir: Making directory sync_test.go:1215: Server side move (if possible) Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7 -> Compressed: TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4 2022/03/02 05:42:21 DEBUG : Compressed: TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4: Using server-side directory move 2022/03/02 05:42:21 INFO : Compressed: TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/02 05:42:21 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/02 05:42:21 DEBUG : empty space: Unchanged skipping 2022/03/02 05:42:21 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/02 05:42:22 DEBUG : Compressed: TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4: Waiting for checks to finish 2022/03/02 05:42:23 INFO : empty space: Deleted 2022/03/02 05:42:23 DEBUG : Compressed: TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4: Waiting for transfers to finish 2022/03/02 05:42:23 INFO : potato3: Deleted 2022/03/02 05:42:24 INFO : potato2: Moved (server-side) 2022/03/02 05:42:25 INFO : potato3: Moved (server-side) 2022/03/02 05:42:25 INFO : tomatoDir: Removing directory 2022/03/02 05:42:26 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: deleted 1 directories 2022/03/02 05:42:26 INFO : There was nothing to transfer 2022/03/02 05:42:30 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-teduviy6zocegos6zehecal1" 2022/03/02 05:42:31 DEBUG : tomatoDir: Making directory 2022/03/02 05:42:32 DEBUG : Compressed: TestCompressDrive:rclone-test-teduviy6zocegos6zehecal1: Using server-side directory move 2022/03/02 05:42:32 INFO : Compressed: TestCompressDrive:rclone-test-teduviy6zocegos6zehecal1: Server side directory move succeeded 2022/03/02 05:42:36 DEBUG : Compressed: TestCompressDrive:rclone-test-teduviy6zocegos6zehecal1: Purge remote 2022/03/02 05:42:37 DEBUG : Compressed: TestCompressDrive:rclone-test-jexewib3lixuxup1tezarur4: Purge remote 2022/03/02 05:42:37 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (41.68s) === RUN TestServerSideMoveOverlap run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1399: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.49s) === RUN TestSyncOverlap run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:42:38 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/rclone-sync-test" --- PASS: TestSyncOverlap (2.68s) === RUN TestSyncCompareDest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:42:41 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:42:43 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/CompareDest" 2022/03/02 05:42:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:42:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:42:50 DEBUG : one: md5 = f97c5d29941bfb1b2fdab0874906ab82 OK 2022/03/02 05:42:50 INFO : one: Copied (new) 2022/03/02 05:42:50 DEBUG : Waiting for deletions to finish 2022/03/02 05:42:53 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:42:53 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/02 05:42:53 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:42:57 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2022/03/02 05:42:57 INFO : one: Copied (replaced existing) 2022/03/02 05:42:57 DEBUG : Waiting for deletions to finish 2022/03/02 05:43:10 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:43:11 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:11 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/02 05:43:11 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:43:11 DEBUG : Waiting for deletions to finish 2022/03/02 05:43:11 INFO : There was nothing to transfer 2022/03/02 05:43:22 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:22 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/02 05:43:22 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:43:23 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:23 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/02 05:43:23 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:43:23 DEBUG : Waiting for deletions to finish 2022/03/02 05:43:23 INFO : There was nothing to transfer 2022/03/02 05:43:28 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:28 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/02 05:43:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:43:29 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:29 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/02 05:43:29 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:43:29 DEBUG : Waiting for deletions to finish 2022/03/02 05:43:29 INFO : There was nothing to transfer 2022/03/02 05:43:34 DEBUG : two: Modification times differ by -119h59m59.877s: 2011-12-30 12:59:59 +0000 UTC, 2011-12-25 12:59:59.123 +0000 UTC 2022/03/02 05:43:34 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/02 05:43:34 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/02 05:43:34 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:43:35 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:35 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/02 05:43:35 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:43:35 DEBUG : Waiting for deletions to finish 2022/03/02 05:43:35 INFO : There was nothing to transfer 2022/03/02 05:43:43 DEBUG : two: Sizes differ (src 5 vs dst 3) 2022/03/02 05:43:43 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:43:44 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:43:44 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/02 05:43:44 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:43:46 DEBUG : two: md5 = 2379e4ce8c3380e996ab0509f17069ad OK 2022/03/02 05:43:46 INFO : two: Copied (new) 2022/03/02 05:43:46 DEBUG : Waiting for deletions to finish 2022/03/02 05:43:57 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:43:57 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:43:57 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:43:57 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:43:58 DEBUG : CompareDest: Rmdir: contains trashed file: "two.json" 2022/03/02 05:43:58 DEBUG : CompareDest: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:43:58 DEBUG : CompareDest: Rmdir: contains trashed file: "one.json" 2022/03/02 05:43:58 DEBUG : CompareDest: Rmdir: contains trashed file: "two.bin" --- PASS: TestSyncCompareDest (78.29s) === RUN TestSyncMultipleCompareDest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:44:10 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dest" 2022/03/02 05:44:13 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/pre-dest1" 2022/03/02 05:44:14 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/pre-dest2" 2022/03/02 05:44:17 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:44:17 DEBUG : 1: Destination found in --compare-dest, skipping 2022/03/02 05:44:19 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:44:19 DEBUG : 2: Destination found in --compare-dest, skipping 2022/03/02 05:44:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dest: Waiting for checks to finish 2022/03/02 05:44:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dest: Waiting for transfers to finish 2022/03/02 05:44:23 DEBUG : 3: md5 = eccbc87e4b5ce2fe28308fd9f2a7baf3 OK 2022/03/02 05:44:23 INFO : 3: Copied (new) 2022/03/02 05:44:23 DEBUG : Waiting for deletions to finish 2022/03/02 05:44:34 DEBUG : pre-dest2: Rmdir: contains trashed file: "2.json" 2022/03/02 05:44:34 DEBUG : pre-dest2: Rmdir: contains trashed file: "2.bin" 2022/03/02 05:44:34 DEBUG : pre-dest1: Rmdir: contains trashed file: "1.json" 2022/03/02 05:44:34 DEBUG : pre-dest1: Rmdir: contains trashed file: "1.bin" 2022/03/02 05:44:35 DEBUG : dest: Rmdir: contains trashed file: "3.bin" 2022/03/02 05:44:35 DEBUG : dest: Rmdir: contains trashed file: "3.json" --- PASS: TestSyncMultipleCompareDest (36.95s) === RUN TestSyncCopyDest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:44:36 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:44:38 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/CopyDest" 2022/03/02 05:44:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:44:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:44:46 DEBUG : one: md5 = f97c5d29941bfb1b2fdab0874906ab82 OK 2022/03/02 05:44:46 INFO : one: Copied (new) 2022/03/02 05:44:46 DEBUG : Waiting for deletions to finish 2022/03/02 05:44:49 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:44:50 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/02 05:44:50 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:44:53 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2022/03/02 05:44:53 INFO : one: Copied (replaced existing) 2022/03/02 05:44:53 DEBUG : Waiting for deletions to finish 2022/03/02 05:45:06 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/BackupDir" 2022/03/02 05:45:09 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:45:10 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:10 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/02 05:45:14 INFO : one: Moved (server-side) 2022/03/02 05:45:16 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2022/03/02 05:45:16 INFO : one: Copied (server-side copy) 2022/03/02 05:45:16 DEBUG : one: Destination found in --copy-dest, using server-side copy 2022/03/02 05:45:16 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:45:16 DEBUG : Waiting for deletions to finish 2022/03/02 05:45:29 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:32 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/02 05:45:32 INFO : two: Copied (server-side copy) 2022/03/02 05:45:32 DEBUG : two: Destination found in --copy-dest, using server-side copy 2022/03/02 05:45:32 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:45:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:33 DEBUG : one: Unchanged skipping 2022/03/02 05:45:33 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:45:33 DEBUG : Waiting for deletions to finish 2022/03/02 05:45:38 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:45:39 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:39 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:39 DEBUG : one: Unchanged skipping 2022/03/02 05:45:39 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:39 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:39 DEBUG : two: Unchanged skipping 2022/03/02 05:45:39 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:45:39 DEBUG : Waiting for deletions to finish 2022/03/02 05:45:39 INFO : There was nothing to transfer 2022/03/02 05:45:54 DEBUG : three: Sizes differ (src 7 vs dst 5) 2022/03/02 05:45:54 DEBUG : three: Destination not found in --copy-dest 2022/03/02 05:45:54 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:45:55 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:55 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:55 DEBUG : two: Unchanged skipping 2022/03/02 05:45:56 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:56 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/02 05:45:56 DEBUG : one: Unchanged skipping 2022/03/02 05:45:56 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:45:58 DEBUG : three: md5 = 1bccb9dccb3e9f6a3f9d2a8bdb54b7f5 OK 2022/03/02 05:45:58 INFO : three: Copied (new) 2022/03/02 05:45:58 DEBUG : Waiting for deletions to finish 2022/03/02 05:46:15 DEBUG : dst: Rmdir: contains trashed file: "three.bin" 2022/03/02 05:46:15 DEBUG : dst: Rmdir: contains trashed file: "three.json" 2022/03/02 05:46:15 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:46:15 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:46:15 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:46:15 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:46:16 DEBUG : CopyDest: Rmdir: contains trashed file: "three.bin" 2022/03/02 05:46:16 DEBUG : CopyDest: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:46:16 DEBUG : CopyDest: Rmdir: contains trashed file: "two.json" 2022/03/02 05:46:16 DEBUG : CopyDest: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:46:16 DEBUG : CopyDest: Rmdir: contains trashed file: "one.json" 2022/03/02 05:46:16 DEBUG : CopyDest: Rmdir: contains trashed file: "three.json" 2022/03/02 05:46:17 DEBUG : BackupDir: Rmdir: contains trashed file: "one.json" 2022/03/02 05:46:17 DEBUG : BackupDir: Rmdir: contains trashed file: "one.bin" --- PASS: TestSyncCopyDest (101.81s) === RUN TestSyncBackupDir run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:46:32 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:46:34 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/backup" 2022/03/02 05:46:36 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:46:36 DEBUG : two: Unchanged skipping 2022/03/02 05:46:36 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:46:36 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/02 05:46:40 INFO : one: Moved (server-side) 2022/03/02 05:46:40 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:46:43 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/02 05:46:43 INFO : one: Copied (new) 2022/03/02 05:46:43 DEBUG : Waiting for deletions to finish 2022/03/02 05:46:46 INFO : three.txt: Moved (server-side) 2022/03/02 05:46:46 INFO : three.txt: Moved into backup dir 2022/03/02 05:46:59 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/02 05:46:59 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:46:59 DEBUG : two: Unchanged skipping 2022/03/02 05:46:59 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:47:01 INFO : one: Deleted 2022/03/02 05:47:03 INFO : one: Moved (server-side) 2022/03/02 05:47:03 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:47:07 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/02 05:47:07 INFO : one: Copied (new) 2022/03/02 05:47:07 DEBUG : Waiting for deletions to finish 2022/03/02 05:47:09 INFO : three.txt: Deleted 2022/03/02 05:47:11 INFO : three.txt: Moved (server-side) 2022/03/02 05:47:11 INFO : three.txt: Moved into backup dir 2022/03/02 05:47:23 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:47:23 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:47:23 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:47:23 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bin" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "three.txt.json" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "one.json" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "three.txt.json" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bin" 2022/03/02 05:47:24 DEBUG : backup: Rmdir: contains trashed file: "one.json" --- PASS: TestSyncBackupDir (66.34s) === RUN TestSyncBackupDirWithSuffix run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:47:38 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:47:40 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/backup" 2022/03/02 05:47:43 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/02 05:47:43 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:47:43 DEBUG : two: Unchanged skipping 2022/03/02 05:47:43 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:47:46 INFO : one: Moved (server-side) to: one.bak 2022/03/02 05:47:46 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:47:49 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/02 05:47:49 INFO : one: Copied (new) 2022/03/02 05:47:49 DEBUG : Waiting for deletions to finish 2022/03/02 05:47:52 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/02 05:47:52 INFO : three.txt: Moved into backup dir 2022/03/02 05:48:04 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/02 05:48:04 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:48:04 DEBUG : two: Unchanged skipping 2022/03/02 05:48:04 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:48:07 INFO : one.bak: Deleted 2022/03/02 05:48:09 INFO : one: Moved (server-side) to: one.bak 2022/03/02 05:48:09 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:48:12 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/02 05:48:12 INFO : one: Copied (new) 2022/03/02 05:48:12 DEBUG : Waiting for deletions to finish 2022/03/02 05:48:14 INFO : three.txt.bak: Deleted 2022/03/02 05:48:17 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/02 05:48:17 INFO : three.txt: Moved into backup dir 2022/03/02 05:48:27 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:48:27 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:48:27 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:48:27 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "one.bak.bin" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "one.bak.json" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "one.bak.bin" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "one.bak.json" 2022/03/02 05:48:28 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.json" --- PASS: TestSyncBackupDirWithSuffix (64.81s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:48:43 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:48:44 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:48:44 DEBUG : pacer: Rate limited, increasing sleep to 1.07244177s 2022/03/02 05:48:45 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:48:46 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/backup" 2022/03/02 05:48:48 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/02 05:48:48 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:48:48 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:48:48 DEBUG : two: Unchanged skipping 2022/03/02 05:48:52 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/02 05:48:52 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:48:55 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/02 05:48:55 INFO : one: Copied (new) 2022/03/02 05:48:55 DEBUG : Waiting for deletions to finish 2022/03/02 05:48:56 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:48:56 DEBUG : pacer: Rate limited, increasing sleep to 1.45091521s 2022/03/02 05:48:56 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:48:58 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/02 05:48:58 INFO : three.txt: Moved into backup dir 2022/03/02 05:49:09 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:49:09 DEBUG : pacer: Rate limited, increasing sleep to 1.437807958s 2022/03/02 05:49:10 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:49:12 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/02 05:49:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:49:12 DEBUG : two: Unchanged skipping 2022/03/02 05:49:12 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:49:14 INFO : one-2019-01-01: Deleted 2022/03/02 05:49:16 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/02 05:49:16 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:49:20 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/02 05:49:20 INFO : one: Copied (new) 2022/03/02 05:49:20 DEBUG : Waiting for deletions to finish 2022/03/02 05:49:22 INFO : three-2019-01-01.txt: Deleted 2022/03/02 05:49:24 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/02 05:49:24 INFO : three.txt: Moved into backup dir 2022/03/02 05:49:35 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:49:35 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:49:35 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:49:35 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/02 05:49:36 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.json" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (68.02s) === RUN TestSyncBackupDirSuffixOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:49:52 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:49:54 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/02 05:49:54 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:49:54 DEBUG : two: Unchanged skipping 2022/03/02 05:49:54 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:49:56 INFO : one: Moved (server-side) to: one.bak 2022/03/02 05:49:56 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:49:59 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/02 05:49:59 INFO : one: Copied (new) 2022/03/02 05:49:59 DEBUG : Waiting for deletions to finish 2022/03/02 05:50:02 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/02 05:50:02 INFO : three.txt: Moved into backup dir 2022/03/02 05:50:15 DEBUG : one.bak: Excluded 2022/03/02 05:50:15 DEBUG : three.txt.bak: Excluded 2022/03/02 05:50:15 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/02 05:50:15 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:50:15 DEBUG : two: Unchanged skipping 2022/03/02 05:50:15 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for checks to finish 2022/03/02 05:50:17 INFO : one.bak: Deleted 2022/03/02 05:50:19 INFO : one: Moved (server-side) to: one.bak 2022/03/02 05:50:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst: Waiting for transfers to finish 2022/03/02 05:50:20 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:50:20 DEBUG : pacer: Rate limited, increasing sleep to 1.049256528s 2022/03/02 05:50:20 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:50:24 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/02 05:50:24 INFO : one: Copied (new) 2022/03/02 05:50:24 DEBUG : Waiting for deletions to finish 2022/03/02 05:50:26 INFO : three.txt.bak: Deleted 2022/03/02 05:50:28 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/02 05:50:28 INFO : three.txt: Moved into backup dir 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" --- PASS: TestSyncBackupDirSuffixOnly (63.40s) === RUN TestSyncSuffix run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:50:55 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:50:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/02 05:51:00 INFO : one: Moved (server-side) to: one.bak 2022/03/02 05:51:03 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/02 05:51:03 INFO : one: Copied (new) 2022/03/02 05:51:04 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:51:04 DEBUG : two: Unchanged skipping 2022/03/02 05:51:06 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/02 05:51:07 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/02 05:51:11 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2022/03/02 05:51:11 INFO : three.txt: Copied (new) 2022/03/02 05:51:22 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/02 05:51:24 INFO : one.bak: Deleted 2022/03/02 05:51:25 INFO : one: Moved (server-side) to: one.bak 2022/03/02 05:51:29 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/02 05:51:29 INFO : one: Copied (new) 2022/03/02 05:51:30 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:51:30 DEBUG : two: Unchanged skipping 2022/03/02 05:51:31 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/02 05:51:33 INFO : three.txt.bak: Deleted 2022/03/02 05:51:35 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/02 05:51:38 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2022/03/02 05:51:38 INFO : three.txt: Copied (new) 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "three.txt.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "three.txt.EwAAAAAAAAA.gz" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:51:52 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" --- PASS: TestSyncSuffix (72.81s) === RUN TestSyncSuffixKeepExtension run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:52:08 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7/dst" 2022/03/02 05:52:11 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/02 05:52:13 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/02 05:52:16 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/02 05:52:16 INFO : one: Copied (new) 2022/03/02 05:52:18 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:52:18 DEBUG : two: Unchanged skipping 2022/03/02 05:52:19 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/02 05:52:21 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/02 05:52:24 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2022/03/02 05:52:24 INFO : three.txt: Copied (new) 2022/03/02 05:52:36 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/02 05:52:38 INFO : one-2019-01-01: Deleted 2022/03/02 05:52:39 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:52:39 DEBUG : pacer: Rate limited, increasing sleep to 1.707547243s 2022/03/02 05:52:40 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:52:40 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/02 05:52:45 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/02 05:52:45 INFO : one: Copied (new) 2022/03/02 05:52:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:52:46 DEBUG : two: Unchanged skipping 2022/03/02 05:52:47 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/02 05:52:49 INFO : three-2019-01-01.txt: Deleted 2022/03/02 05:52:50 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:52:50 DEBUG : pacer: Rate limited, increasing sleep to 1.434915558s 2022/03/02 05:52:50 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:52:52 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/02 05:52:56 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2022/03/02 05:52:56 INFO : three.txt: Copied (new) 2022/03/02 05:53:09 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:53:09 DEBUG : pacer: Rate limited, increasing sleep to 1.77388706s 2022/03/02 05:53:09 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:53:09 DEBUG : pacer: Rate limited, increasing sleep to 2.025531539s 2022/03/02 05:53:11 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "three.txt.EwAAAAAAAAA.gz" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "three.txt.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/02 05:53:11 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" --- PASS: TestSyncSuffixKeepExtension (80.71s) === RUN TestSyncUTFNorm run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:53:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:53:19 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2022/03/02 05:53:19 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:53:24 DEBUG : Testêé: md5 = ce114e4501d2f4e2dcea3e17b546f339 OK 2022/03/02 05:53:24 INFO : Testêé: Copied (replaced existing) to: Testêé 2022/03/02 05:53:24 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (13.06s) === RUN TestSyncImmutable run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:53:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:53:28 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:53:31 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/02 05:53:31 INFO : existing: Copied (new) 2022/03/02 05:53:31 DEBUG : Waiting for deletions to finish 2022/03/02 05:53:34 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:53:34 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2022/03/02 05:53:34 ERROR : existing: Source and destination exist but do not match: immutable file modified 2022/03/02 05:53:34 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:53:34 ERROR : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: not deleting files as there were IO errors 2022/03/02 05:53:34 ERROR : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: not deleting directories as there were IO errors --- PASS: TestSyncImmutable (9.96s) === RUN TestSyncIgnoreCase run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:53:42 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:53:42 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:53:42 DEBUG : existing: Unchanged skipping 2022/03/02 05:53:42 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:53:42 DEBUG : Waiting for deletions to finish 2022/03/02 05:53:42 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (7.92s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Soft run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" sync_test.go:1989: This test only runs on local --- PASS: TestMaxTransfer (1.53s) --- SKIP: TestMaxTransfer/Hard (0.52s) --- SKIP: TestMaxTransfer/Soft (0.49s) --- SKIP: TestMaxTransfer/Cautious (0.52s) === RUN TestSyncConcurrentDelete run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 05:56:09 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:09 DEBUG : pacer: Rate limited, increasing sleep to 1.018487141s 2022/03/02 05:56:09 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:09 DEBUG : pacer: Rate limited, increasing sleep to 2.916309404s 2022/03/02 05:56:10 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:35 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both0: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 05:56:35 DEBUG : both10: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both13: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both11: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both14: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both16: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both17: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both18: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both19: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both2: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both3: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both12: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both4: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both15: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both5: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both7: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 05:56:35 DEBUG : both9: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both6: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both1: Unchanged skipping 2022/03/02 05:56:35 DEBUG : both8: Unchanged skipping 2022/03/02 05:56:35 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 05:56:35 DEBUG : Waiting for deletions to finish 2022/03/02 05:56:35 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:35 DEBUG : pacer: Rate limited, increasing sleep to 1.482533775s 2022/03/02 05:56:35 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:35 DEBUG : pacer: Rate limited, increasing sleep to 2.932548971s 2022/03/02 05:56:35 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:35 DEBUG : pacer: Rate limited, increasing sleep to 4.619721446s 2022/03/02 05:56:36 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:36 DEBUG : pacer: Rate limited, increasing sleep to 8.71040601s 2022/03/02 05:56:36 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:38 INFO : only1: Deleted 2022/03/02 05:56:38 INFO : only2: Deleted 2022/03/02 05:56:38 INFO : only18: Deleted 2022/03/02 05:56:38 INFO : only16: Deleted 2022/03/02 05:56:38 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:38 DEBUG : pacer: Rate limited, increasing sleep to 1.579428588s 2022/03/02 05:56:38 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:38 DEBUG : pacer: Rate limited, increasing sleep to 2.990969531s 2022/03/02 05:56:39 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:41 INFO : only0: Deleted 2022/03/02 05:56:41 INFO : only9: Deleted 2022/03/02 05:56:41 INFO : only5: Deleted 2022/03/02 05:56:41 INFO : only13: Deleted 2022/03/02 05:56:41 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:41 DEBUG : pacer: Rate limited, increasing sleep to 1.110202817s 2022/03/02 05:56:41 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:42 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:42 DEBUG : pacer: Rate limited, increasing sleep to 1.02807797s 2022/03/02 05:56:42 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:43 INFO : only15: Deleted 2022/03/02 05:56:43 INFO : only3: Deleted 2022/03/02 05:56:43 INFO : only19: Deleted 2022/03/02 05:56:43 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:43 DEBUG : pacer: Rate limited, increasing sleep to 1.727503118s 2022/03/02 05:56:44 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:44 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:44 DEBUG : pacer: Rate limited, increasing sleep to 1.287517042s 2022/03/02 05:56:44 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:46 INFO : only11: Deleted 2022/03/02 05:56:46 INFO : only10: Deleted 2022/03/02 05:56:46 INFO : only14: Deleted 2022/03/02 05:56:46 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:56:46 DEBUG : pacer: Rate limited, increasing sleep to 1.899932613s 2022/03/02 05:56:47 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:56:47 INFO : only17: Deleted 2022/03/02 05:56:49 INFO : only7: Deleted 2022/03/02 05:56:49 INFO : only8: Deleted 2022/03/02 05:56:49 INFO : only12: Deleted 2022/03/02 05:56:50 INFO : only4: Deleted 2022/03/02 05:56:50 INFO : only6: Deleted 2022/03/02 05:56:50 INFO : There was nothing to transfer 2022/03/02 05:57:00 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:57:00 DEBUG : pacer: Rate limited, increasing sleep to 1.693579196s 2022/03/02 05:57:00 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 05:57:37 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 05:57:37 DEBUG : pacer: Rate limited, increasing sleep to 1.69965786s 2022/03/02 05:57:37 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentDelete (233.57s) === RUN TestSyncConcurrentTruncate run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7", Local "Local file system at /tmp/rclone197051821", Modify Window "1ms" 2022/03/02 06:00:19 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 06:00:19 DEBUG : pacer: Rate limited, increasing sleep to 1.239633674s 2022/03/02 06:00:19 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 06:00:19 DEBUG : pacer: Rate limited, increasing sleep to 2.86142582s 2022/03/02 06:00:20 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 06:00:20 DEBUG : pacer: Rate limited, increasing sleep to 4.965890577s 2022/03/02 06:00:23 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 06:00:41 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both0: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both1: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both10: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both11: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both12: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both13: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both14: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both15: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both16: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both17: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both18: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both19: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both2: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both3: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both4: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both5: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both6: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both7: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both8: Unchanged skipping 2022/03/02 06:00:41 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/02 06:00:41 DEBUG : both9: Unchanged skipping 2022/03/02 06:00:41 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2022/03/02 06:00:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for checks to finish 2022/03/02 06:00:41 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Waiting for transfers to finish 2022/03/02 06:00:45 DEBUG : only11: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:45 INFO : only11: Copied (replaced existing) 2022/03/02 06:00:45 DEBUG : only10: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:45 INFO : only10: Copied (replaced existing) 2022/03/02 06:00:45 DEBUG : only0: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:45 INFO : only0: Copied (replaced existing) 2022/03/02 06:00:45 DEBUG : only1: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:45 INFO : only1: Copied (replaced existing) 2022/03/02 06:00:48 DEBUG : only12: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:48 INFO : only12: Copied (replaced existing) 2022/03/02 06:00:48 DEBUG : only13: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:48 INFO : only13: Copied (replaced existing) 2022/03/02 06:00:48 DEBUG : only14: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:48 INFO : only14: Copied (replaced existing) 2022/03/02 06:00:48 DEBUG : only15: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:48 INFO : only15: Copied (replaced existing) 2022/03/02 06:00:49 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 06:00:49 DEBUG : pacer: Rate limited, increasing sleep to 1.698247428s 2022/03/02 06:00:49 DEBUG : TestDrive: Loaded invalid token from config file - ignoring 2022/03/02 06:00:49 DEBUG : Config file has changed externaly - reloading 2022/03/02 06:00:49 DEBUG : Saving config "token" in section "TestDrive" of the config file 2022/03/02 06:00:49 DEBUG : TestDrive: Saved new token in config file 2022/03/02 06:00:50 DEBUG : pacer: Reducing sleep to 0s 2022/03/02 06:00:50 DEBUG : only19: Received error: googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded - low level retry 1/10 2022/03/02 06:00:52 DEBUG : only16: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:52 INFO : only16: Copied (replaced existing) 2022/03/02 06:00:52 DEBUG : only17: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:52 INFO : only17: Copied (replaced existing) 2022/03/02 06:00:52 DEBUG : only18: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:52 INFO : only18: Copied (replaced existing) 2022/03/02 06:00:54 DEBUG : only19: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:54 INFO : only19: Copied (replaced existing) 2022/03/02 06:00:56 DEBUG : only3: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:56 INFO : only3: Copied (replaced existing) 2022/03/02 06:00:56 DEBUG : only4: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:56 INFO : only4: Copied (replaced existing) 2022/03/02 06:00:56 DEBUG : only2: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:56 INFO : only2: Copied (replaced existing) 2022/03/02 06:00:57 DEBUG : only5: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:57 INFO : only5: Copied (replaced existing) 2022/03/02 06:00:59 DEBUG : only8: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:59 INFO : only8: Copied (replaced existing) 2022/03/02 06:00:59 DEBUG : only7: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:59 INFO : only7: Copied (replaced existing) 2022/03/02 06:00:59 DEBUG : only6: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:00:59 INFO : only6: Copied (replaced existing) 2022/03/02 06:01:00 DEBUG : only9: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/02 06:01:00 INFO : only9: Copied (replaced existing) 2022/03/02 06:01:00 DEBUG : Waiting for deletions to finish fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:351 run.go:342 sync_test.go:2058 sync_test.go:2066 Error: Should be true Test: TestSyncConcurrentTruncate Messages: listing wrong, want both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only0 (0), only1 (0), only10 (0), only11 (0), only12 (0), only13 (0), only14 (0), only15 (0), only16 (0), only17 (0), only18 (0), only19 (0), only2 (0), only3 (0), only4 (0), only5 (0), only6 (0), only7 (0), only8 (0), only9 (0) got both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only0 (0), only1 (0), only10 (0), only11 (0), only12 (0), only13 (0), only14 (0), only15 (0), only16 (0), only17 (0), only18 (0), only2 (0), only3 (0), only4 (0), only5 (0), only6 (0), only7 (0), only8 (0), only9 (0) fstest.go:204: Not found "only19" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 fstest.go:351 run.go:342 sync_test.go:2058 sync_test.go:2066 Error: Not equal: expected: 0 actual : 1 Test: TestSyncConcurrentTruncate Messages: 1 objects not found 2022/03/02 06:01: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/03/02 06:01:54 DEBUG : pacer: Rate limited, increasing sleep to 1.250305763s 2022/03/02 06:01:55 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/02 06:01:55 DEBUG : pacer: Rate limited, increasing sleep to 2.938460357s 2022/03/02 06:01:56 DEBUG : pacer: Reducing sleep to 0s --- FAIL: TestSyncConcurrentTruncate (304.92s) FAIL 2022/03/02 06:02:45 DEBUG : Compressed: TestCompressDrive:rclone-test-hawiliw4vuyecug8suhunar7: Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCompressDrive: -verbose" - Finished ERROR in 32m36.832197283s (try 1/5): exit status 1: Failed [TestSyncConcurrentTruncate]