"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5)
2021/11/13 06:27:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3"
2021/11/13 06:27:30 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/11/13 06:27:30 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0"
2021/11/13 06:27:31 DEBUG : Creating backend with remote "/tmp/rclone3361733286"
=== RUN   TestPipe
--- PASS: TestPipe (0.00s)
=== RUN   TestPipeConcurrent
--- PASS: TestPipeConcurrent (0.02s)
=== RUN   TestPipeOrderBy
=== RUN   TestPipeOrderBy/#00
=== RUN   TestPipeOrderBy/size
=== RUN   TestPipeOrderBy/name
=== RUN   TestPipeOrderBy/modtime
=== RUN   TestPipeOrderBy/size,ascending
=== RUN   TestPipeOrderBy/name,asc
=== RUN   TestPipeOrderBy/modtime,ascending
=== RUN   TestPipeOrderBy/size,descending
=== RUN   TestPipeOrderBy/name,desc
=== RUN   TestPipeOrderBy/modtime,descending
=== RUN   TestPipeOrderBy/size,mixed,50
=== RUN   TestPipeOrderBy/size,mixed,51
--- PASS: TestPipeOrderBy (0.00s)
    --- PASS: TestPipeOrderBy/#00 (0.00s)
    --- PASS: TestPipeOrderBy/size (0.00s)
    --- PASS: TestPipeOrderBy/name (0.00s)
    --- PASS: TestPipeOrderBy/modtime (0.00s)
    --- PASS: TestPipeOrderBy/size,ascending (0.00s)
    --- PASS: TestPipeOrderBy/name,asc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,ascending (0.00s)
    --- PASS: TestPipeOrderBy/size,descending (0.00s)
    --- PASS: TestPipeOrderBy/name,desc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,descending (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s)
=== RUN   TestNewLess
=== RUN   TestNewLess/blankOK
=== RUN   TestNewLess/tooManyParts
=== RUN   TestNewLess/tooManyParts2
=== RUN   TestNewLess/badMixed
=== RUN   TestNewLess/unknownComparison
=== RUN   TestNewLess/unknownSortDirection
=== RUN   TestNewLess/size
=== RUN   TestNewLess/name
=== RUN   TestNewLess/modtime
=== RUN   TestNewLess/size,ascending
=== RUN   TestNewLess/name,asc
=== RUN   TestNewLess/modtime,ascending
=== RUN   TestNewLess/size,descending
=== RUN   TestNewLess/name,desc
=== RUN   TestNewLess/modtime,descending
=== RUN   TestNewLess/modtime,mixed
=== RUN   TestNewLess/modtime,mixed,30
--- PASS: TestNewLess (0.00s)
    --- PASS: TestNewLess/blankOK (0.00s)
    --- PASS: TestNewLess/tooManyParts (0.00s)
    --- PASS: TestNewLess/tooManyParts2 (0.00s)
    --- PASS: TestNewLess/badMixed (0.00s)
    --- PASS: TestNewLess/unknownComparison (0.00s)
    --- PASS: TestNewLess/unknownSortDirection (0.00s)
    --- PASS: TestNewLess/size (0.00s)
    --- PASS: TestNewLess/name (0.00s)
    --- PASS: TestNewLess/modtime (0.00s)
    --- PASS: TestNewLess/size,ascending (0.00s)
    --- PASS: TestNewLess/name,asc (0.00s)
    --- PASS: TestNewLess/modtime,ascending (0.00s)
    --- PASS: TestNewLess/size,descending (0.00s)
    --- PASS: TestNewLess/name,desc (0.00s)
    --- PASS: TestNewLess/modtime,descending (0.00s)
    --- PASS: TestNewLess/modtime,mixed (0.00s)
    --- PASS: TestNewLess/modtime,mixed,30 (0.00s)
=== RUN   TestRcCopy
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcCopy (0.00s)
=== RUN   TestRcMove
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcMove (0.00s)
=== RUN   TestRcSync
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcSync (0.00s)
=== RUN   TestCopyWithDryRun
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:32 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2021/11/13 06:27:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
--- PASS: TestCopyWithDryRun (2.03s)
=== RUN   TestCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:27:36 DEBUG : sub dir/hello world: md5 = 49a802ecb3dad755ef8653610dde12ad OK
2021/11/13 06:27:36 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:27:38 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopy (5.65s)
=== RUN   TestCopyMissingDirectory
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:39 DEBUG : Creating backend with remote "/non-existing"
2021/11/13 06:27:39 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2021/11/13 06:27:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
--- PASS: TestCopyMissingDirectory (0.75s)
=== RUN   TestCopyNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:27:42 DEBUG : sub dir/hello world: md5 = bcc46200a7e9406dafd1c7d55fb28108 OK
2021/11/13 06:27:42 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:27:45 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyNoTraverse (6.14s)
=== RUN   TestCopyCheckFirst
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:46 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Running all checks before starting transfers
2021/11/13 06:27:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:46 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Checks finished, now starting transfers
2021/11/13 06:27:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:27:48 DEBUG : sub dir/hello world: md5 = 7c6cd91ac7472be3fe93069bea0d5e90 OK
2021/11/13 06:27:48 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:27:50 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyCheckFirst (5.87s)
=== RUN   TestSyncNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:51 ERROR : Ignoring --no-traverse with sync
2021/11/13 06:27:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:27:54 DEBUG : sub dir/hello world: md5 = 9d84f1b01a11b5040b47b11c9701337d OK
2021/11/13 06:27:54 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:27:54 DEBUG : Waiting for deletions to finish
2021/11/13 06:27:56 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncNoTraverse (5.49s)
=== RUN   TestCopyWithDepth
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:27:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:27:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:27:59 DEBUG : hello world2: md5 = b2663a0886bb7d742aa899c7a9c2210e OK
2021/11/13 06:27:59 INFO  : hello world2: Copied (new)
--- PASS: TestCopyWithDepth (3.15s)
=== RUN   TestCopyWithFilesFrom
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:00 DEBUG : hello world2: Excluded
2021/11/13 06:28:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:02 DEBUG : potato2: md5 = a142e27de4aae60d0a68d79630067b81 OK
2021/11/13 06:28:02 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFrom (3.47s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:05 DEBUG : potato2: md5 = 1530dc57fe6ed1cee28d2111d952d087 OK
2021/11/13 06:28:05 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFromAndNoTraverse (3.03s)
=== RUN   TestCopyEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:07 DEBUG : sub dir2: Making directory
2021/11/13 06:28:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:09 DEBUG : sub dir/hello world: md5 = a0b7bb8a8f9980ab5ee1abbfc76d051a OK
2021/11/13 06:28:09 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:28:09 DEBUG : sub dir2: Making directory
2021/11/13 06:28:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': copied 1 directories
2021/11/13 06:28:13 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyEmptyDirectories (7.13s)
=== RUN   TestMoveEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:14 DEBUG : sub dir2: Making directory
2021/11/13 06:28:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:16 DEBUG : sub dir/hello world: md5 = 33381966032097fd55d6d6695bb70f4c OK
2021/11/13 06:28:16 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:28:16 INFO  : sub dir/hello world: Deleted
2021/11/13 06:28:16 DEBUG : sub dir: Making directory
2021/11/13 06:28:16 DEBUG : sub dir2: Making directory
2021/11/13 06:28:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': copied 2 directories
2021/11/13 06:28:20 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestMoveEmptyDirectories (7.33s)
=== RUN   TestSyncEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:21 DEBUG : sub dir2: Making directory
2021/11/13 06:28:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:24 DEBUG : sub dir/hello world: md5 = c30df3105791c0dc14af681ca5e2b7ac OK
2021/11/13 06:28:24 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:28:24 DEBUG : sub dir2: Making directory
2021/11/13 06:28:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': copied 1 directories
2021/11/13 06:28:25 DEBUG : Waiting for deletions to finish
2021/11/13 06:28:28 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncEmptyDirectories (7.38s)
=== RUN   TestServerSideCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:31 DEBUG : sub dir/hello world: md5 = 42ea3879670fb2c36930841804ce22bd OK
2021/11/13 06:28:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-ticokav9yivanuy9nebiwaw7"
2021/11/13 06:28:31 DEBUG : Config file has changed externaly - reloading
2021/11/13 06:28:31 DEBUG : Creating backend with remote "TestDrive:crypt/ndn0gmqqip8dlkmkjkpmcd9srhnkguvremv3ntqdumdrrr4cc11h34i1mpjs651tog791lajnebg4"
    sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3' -> Encrypted drive 'TestCryptDrive:rclone-test-ticokav9yivanuy9nebiwaw7'
2021/11/13 06:28:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ticokav9yivanuy9nebiwaw7': Waiting for checks to finish
2021/11/13 06:28:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ticokav9yivanuy9nebiwaw7': Waiting for transfers to finish
2021/11/13 06:28:36 INFO  : sub dir/hello world: Copied (server-side copy)
2021/11/13 06:28:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ticokav9yivanuy9nebiwaw7': Purge remote
2021/11/13 06:28:39 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestServerSideCopy (11.05s)
=== RUN   TestCopyAfterDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:42 DEBUG : sub dir/hello world: md5 = f744a4581362e37234c2549a1dffe14d OK
2021/11/13 06:28:42 ERROR : : error listing: directory not found
2021/11/13 06:28:43 DEBUG : Local file system at /tmp/rclone3361733286: Making directory
2021/11/13 06:28:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:45 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyAfterDelete (6.63s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:48 DEBUG : sub dir/hello world: md5 = 73866559b15150876ca36fe194a0cda3 OK
2021/11/13 06:28:49 DEBUG : Local file system at /tmp/rclone3361733286: Waiting for checks to finish
2021/11/13 06:28:49 DEBUG : Local file system at /tmp/rclone3361733286: Waiting for transfers to finish
2021/11/13 06:28:50 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:28:52 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyRedownload (7.01s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:55 DEBUG : check sum: md5 = 26f06b7ee09d0922fe2fb8f11eee61df OK
2021/11/13 06:28:55 INFO  : check sum: Copied (new)
2021/11/13 06:28:55 DEBUG : Waiting for deletions to finish
2021/11/13 06:28:56 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2021/11/13 06:28:56 DEBUG : check sum: Size of src and dst objects identical
2021/11/13 06:28:56 DEBUG : check sum: Unchanged skipping
2021/11/13 06:28:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:56 DEBUG : Waiting for deletions to finish
2021/11/13 06:28:56 INFO  : There was nothing to transfer
--- PASS: TestSyncBasedOnCheckSum (3.73s)
=== RUN   TestSyncSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:28:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:59 DEBUG : sizeonly: md5 = 2f12b582c5514b56fb2532d1ad116433 OK
2021/11/13 06:28:59 INFO  : sizeonly: Copied (new)
2021/11/13 06:28:59 DEBUG : Waiting for deletions to finish
2021/11/13 06:28:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:28:59 DEBUG : sizeonly: Sizes identical
2021/11/13 06:28:59 DEBUG : sizeonly: Unchanged skipping
2021/11/13 06:28:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:28:59 DEBUG : Waiting for deletions to finish
2021/11/13 06:28:59 INFO  : There was nothing to transfer
--- PASS: TestSyncSizeOnly (3.79s)
=== RUN   TestSyncIgnoreSize
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:02 DEBUG : ignore-size: md5 = 237a84c2a2cc45803536c8ddb5adccfc OK
2021/11/13 06:29:02 INFO  : ignore-size: Copied (new)
2021/11/13 06:29:02 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:03 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:29:03 DEBUG : ignore-size: Unchanged skipping
2021/11/13 06:29:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:03 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:03 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreSize (3.74s)
=== RUN   TestSyncIgnoreTimes
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:06 DEBUG : existing: md5 = e218f09ff2747ba6fc6c13cf7663f1bc OK
2021/11/13 06:29:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:06 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:29:06 DEBUG : existing: Unchanged skipping
2021/11/13 06:29:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:06 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:06 INFO  : There was nothing to transfer
2021/11/13 06:29:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:07 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2021/11/13 06:29:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:08 DEBUG : existing: md5 = 80025332a2272dc5ac1778fa3f8b93c5 OK
2021/11/13 06:29:08 INFO  : existing: Copied (replaced existing)
2021/11/13 06:29:08 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncIgnoreTimes (4.83s)
=== RUN   TestSyncIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:11 DEBUG : existing: md5 = dc3d3771cdc1de21a0b145a78a806dfe OK
2021/11/13 06:29:11 INFO  : existing: Copied (new)
2021/11/13 06:29:11 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:11 DEBUG : existing: Destination exists, skipping
2021/11/13 06:29:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:11 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:11 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreExisting (3.57s)
=== RUN   TestSyncIgnoreErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:15 DEBUG : b/potato: md5 = b62b9c861cde01f9cbb6682aaf62f39c OK
2021/11/13 06:29:18 DEBUG : c/non empty space: md5 = 56b94ac1144c0ab38583d9a21f553ade OK
2021/11/13 06:29:18 DEBUG : d: Making directory
2021/11/13 06:29:20 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:29:20 DEBUG : c/non empty space: Unchanged skipping
2021/11/13 06:29:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:23 DEBUG : a/potato2: md5 = 65fcd489e2137189ab07cc6b1f11b025 OK
2021/11/13 06:29:23 INFO  : a/potato2: Copied (new)
2021/11/13 06:29:23 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:24 INFO  : b/potato: Deleted
2021/11/13 06:29:24 INFO  : d: Removing directory
2021/11/13 06:29:25 INFO  : b: Removing directory
2021/11/13 06:29:25 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2021/11/13 06:29:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': deleted 2 directories
2021/11/13 06:29:28 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2021/11/13 06:29:29 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncIgnoreErrors (17.51s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:32 DEBUG : empty space: md5 = a730e6b56f945eab25192310b42deadc OK
2021/11/13 06:29:32 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2021/11/13 06:29:32 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2021/11/13 06:29:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:32 DEBUG : Waiting for deletions to finish
2021/11/13 06:29:33 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2021/11/13 06:29:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:34 DEBUG : empty space: md5 = c0fab6f9c00033b7e51824c5746c7fa4 OK
2021/11/13 06:29:34 INFO  : empty space: Copied (replaced existing)
2021/11/13 06:29:34 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingModtimeOnly (5.31s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:577: Can't check this if no hashes supported
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.53s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:38 DEBUG : foo: md5 = cc3565c2f621aed7470014a9120ec4a1 OK
2021/11/13 06:29:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:38 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2021/11/13 06:29:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:40 DEBUG : foo: md5 = 957ad36c23203b37107bf6519ff0cec4 OK
2021/11/13 06:29:40 INFO  : foo: Copied (replaced existing)
2021/11/13 06:29:40 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncDoesntUpdateModtime (4.91s)
=== RUN   TestSyncAfterAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:43 DEBUG : empty space: md5 = 751c2350cfe79640be7336d469041a8d OK
2021/11/13 06:29:43 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:29:43 DEBUG : empty space: Unchanged skipping
2021/11/13 06:29:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:45 DEBUG : potato: md5 = 6da5a89350e8799f956e722d89db1811 OK
2021/11/13 06:29:45 INFO  : potato: Copied (new)
2021/11/13 06:29:45 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterAddingAFile (5.75s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:48 DEBUG : potato: md5 = ce3b97f47517a3cd7b97e209db367d8a OK
2021/11/13 06:29:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:49 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2021/11/13 06:29:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:50 DEBUG : potato: md5 = a93cf871ee9a928a3f4f80cc1bc023ce OK
2021/11/13 06:29:50 INFO  : potato: Copied (replaced existing)
2021/11/13 06:29:50 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingFilesSizeOnly (4.67s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:53 DEBUG : potato: md5 = ef122a44db00665187e306dac22ee9f0 OK
2021/11/13 06:29:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:29:54 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC
2021/11/13 06:29:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:29:55 DEBUG : potato: md5 = 52cb8b39c24e59629789bdee0b3848ca OK
2021/11/13 06:29:55 INFO  : potato: Copied (replaced existing)
2021/11/13 06:29:55 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingContentsOnly (6.09s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:29:59 DEBUG : potato: md5 = 908910ef51bde87babd78210107d4606 OK
2021/11/13 06:30:01 DEBUG : empty space: md5 = 5f7fa4816471e8e5c2275adcd1be41c6 OK
2021/11/13 06:30:01 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2021/11/13 06:30:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:30:01 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:30:01 DEBUG : empty space: Unchanged skipping
2021/11/13 06:30:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:30:01 DEBUG : Waiting for deletions to finish
2021/11/13 06:30:01 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.45s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:30:04 DEBUG : potato: md5 = 8031f96d2f165bb472b4699144bb1d28 OK
2021/11/13 06:30:06 DEBUG : empty space: md5 = a90f6190aa382c958bba731fa973e52c OK
2021/11/13 06:30:06 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:30:06 DEBUG : empty space: Unchanged skipping
2021/11/13 06:30:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:30:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:30:08 DEBUG : potato2: md5 = 7ca8a39b66d5378c1363cb97d4fe6d3e OK
2021/11/13 06:30:08 INFO  : potato2: Copied (new)
2021/11/13 06:30:08 DEBUG : Waiting for deletions to finish
2021/11/13 06:30:09 INFO  : potato: Deleted
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.62s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:30:13 DEBUG : b/potato: md5 = 49080da7d38c795a8dc2768ead0c4a2b OK
2021/11/13 06:30:16 DEBUG : c/non empty space: md5 = 7b862efe9440d5a546df2404bf443c2d OK
2021/11/13 06:30:16 DEBUG : d: Making directory
2021/11/13 06:30:17 DEBUG : d/e: Making directory
2021/11/13 06:30:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:30:20 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:30:20 DEBUG : c/non empty space: Unchanged skipping
2021/11/13 06:30:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:30:22 DEBUG : a/potato2: md5 = 39bd66f29d8e5db93797601565c025a5 OK
2021/11/13 06:30:22 INFO  : a/potato2: Copied (new)
2021/11/13 06:30:22 DEBUG : Waiting for deletions to finish
2021/11/13 06:30:23 INFO  : b/potato: Deleted
2021/11/13 06:30:23 INFO  : d/e: Removing directory
2021/11/13 06:30:24 INFO  : d: Removing directory
2021/11/13 06:30:24 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8"
2021/11/13 06:30:25 INFO  : b: Removing directory
2021/11/13 06:30:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:30:25 DEBUG : pacer: Rate limited, increasing sleep to 1.39490915s
2021/11/13 06:30:25 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:30:25 DEBUG : pacer: Rate limited, increasing sleep to 2.945599487s
2021/11/13 06:30:27 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:30:27 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2021/11/13 06:30:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': deleted 3 directories
2021/11/13 06:30:33 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2021/11/13 06:30:34 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (24.20s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:30:37 DEBUG : b/potato: md5 = 17091ed1141c67259f573f44cee09fd3 OK
2021/11/13 06:30:40 DEBUG : c/non empty space: md5 = 415e6c93b341c85862a59af8522cf99d OK
2021/11/13 06:30:40 DEBUG : d: Making directory
2021/11/13 06:30:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:30:43 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:30:43 DEBUG : c/non empty space: Unchanged skipping
2021/11/13 06:30:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:30:46 DEBUG : a/potato2: md5 = c10fc61d3872e9e6814d2e9696c64f29 OK
2021/11/13 06:30:46 INFO  : a/potato2: Copied (new)
2021/11/13 06:30:46 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': not deleting files as there were IO errors
2021/11/13 06:30:46 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': not deleting directories as there were IO errors
2021/11/13 06:30:50 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2021/11/13 06:30:51 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2021/11/13 06:30:52 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (17.97s)
=== RUN   TestSyncDeleteAfter
--- PASS: TestSyncDeleteAfter (0.00s)
=== RUN   TestSyncDeleteDuring
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:30:54 DEBUG : potato: md5 = 0cb190a761c2b988676544053f84ff9a OK
2021/11/13 06:30:56 DEBUG : empty space: md5 = 98b81e706005f3caa9df39440ac6b3fb OK
2021/11/13 06:30:56 DEBUG : Waiting for deletions to finish
2021/11/13 06:30:57 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:30:57 DEBUG : empty space: Unchanged skipping
2021/11/13 06:30:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:30:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:30:57 INFO  : potato: Deleted
2021/11/13 06:30:58 DEBUG : potato2: md5 = eb4dd6db72f71803082fc6fbd1bfa297 OK
2021/11/13 06:30:58 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteDuring (7.58s)
=== RUN   TestSyncDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:31:02 DEBUG : potato: md5 = dd858576e484c7ad8ab3c57baf1be9a2 OK
2021/11/13 06:31:04 DEBUG : empty space: md5 = e2a2ffb4beddfdc2dfab6443dd3e894a OK
2021/11/13 06:31:04 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:05 INFO  : potato: Deleted
2021/11/13 06:31:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:05 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:31:05 DEBUG : empty space: Unchanged skipping
2021/11/13 06:31:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:07 DEBUG : potato2: md5 = 3fd10b264f4cd0e96956242a1ce36114 OK
2021/11/13 06:31:07 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteBefore (8.97s)
=== RUN   TestCopyDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:31:11 DEBUG : potato: md5 = 10284380c8ab9ba6e278edd1fdecd434 OK
2021/11/13 06:31:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:13 DEBUG : potato2: md5 = 635b0cc747fc654f5abba99b39fc3c30 OK
2021/11/13 06:31:13 INFO  : potato2: Copied (new)
--- PASS: TestCopyDeleteBefore (5.75s)
=== RUN   TestSyncWithExclude
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:31:17 DEBUG : potato2: md5 = 790b6ca6825ec110cbb8981ffcb7ccdf OK
2021/11/13 06:31:18 DEBUG : empty space: md5 = 6749fcdd4be05870308c4f847d3e7626 OK
2021/11/13 06:31:18 DEBUG : enormous: Excluded
2021/11/13 06:31:18 DEBUG : potato2: Excluded
2021/11/13 06:31:19 DEBUG : potato2: Excluded from sync (and deletion)
2021/11/13 06:31:19 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:31:19 DEBUG : empty space: Unchanged skipping
2021/11/13 06:31:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:19 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:19 INFO  : There was nothing to transfer
2021/11/13 06:31:19 DEBUG : enormous: Excluded
2021/11/13 06:31:19 DEBUG : potato2: Excluded
2021/11/13 06:31:19 DEBUG : potato2: Excluded from sync (and deletion)
2021/11/13 06:31:19 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2021/11/13 06:31:19 DEBUG : empty space: Unchanged skipping
2021/11/13 06:31:19 DEBUG : Local file system at /tmp/rclone3361733286: Waiting for checks to finish
2021/11/13 06:31:19 DEBUG : Local file system at /tmp/rclone3361733286: Waiting for transfers to finish
2021/11/13 06:31:19 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:19 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExclude (6.22s)
=== RUN   TestSyncWithExcludeAndDeleteExcluded
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:31:23 DEBUG : potato2: md5 = c79c42dabe4c080a84b6a8a3243a4c72 OK
2021/11/13 06:31:24 DEBUG : empty space: md5 = 060b5eaff78aacbcfbf4f3a8560e8e5e OK
2021/11/13 06:31:26 DEBUG : enormous: md5 = fb10b5fd2198c03bb3b05614512a9b21 OK
2021/11/13 06:31:26 DEBUG : enormous: Excluded
2021/11/13 06:31:26 DEBUG : potato2: Excluded
2021/11/13 06:31:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:26 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:31:26 DEBUG : empty space: Unchanged skipping
2021/11/13 06:31:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:26 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:27 INFO  : potato2: Deleted
2021/11/13 06:31:27 INFO  : enormous: Deleted
2021/11/13 06:31:27 INFO  : There was nothing to transfer
2021/11/13 06:31:28 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2021/11/13 06:31:28 DEBUG : Local file system at /tmp/rclone3361733286: Waiting for checks to finish
2021/11/13 06:31:28 DEBUG : empty space: Unchanged skipping
2021/11/13 06:31:28 DEBUG : Local file system at /tmp/rclone3361733286: Waiting for transfers to finish
2021/11/13 06:31:28 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:28 INFO  : potato2: Deleted
2021/11/13 06:31:28 INFO  : enormous: Deleted
2021/11/13 06:31:28 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExcludeAndDeleteExcluded (7.58s)
=== RUN   TestSyncWithUpdateOlder
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:31:30 DEBUG : one: md5 = d285e2c67a9186f29aed010b5177bd2d OK
2021/11/13 06:31:32 DEBUG : two: md5 = e64a25bcb6588c02ce67e05f4a029e05 OK
2021/11/13 06:31:33 DEBUG : three: md5 = 23dc93edb794628211315c6e62964021 OK
2021/11/13 06:31:35 DEBUG : four: md5 = 5cafaa34cbddba04f2fd13c6f9a68190 OK
2021/11/13 06:31:35 DEBUG : four: Sizes differ (src 4 vs dst 8)
2021/11/13 06:31:35 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring
2021/11/13 06:31:35 DEBUG : one: Destination is newer than source, skipping
2021/11/13 06:31:35 DEBUG : three: Sizes identical
2021/11/13 06:31:35 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping
2021/11/13 06:31:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:36 DEBUG : four: md5 = 5aa86737014256223db4f002853df9dd OK
2021/11/13 06:31:36 INFO  : four: Copied (replaced existing)
2021/11/13 06:31:37 DEBUG : two: md5 = 7eeb1d2319aa5832c3ab2e5cb5ba2f68 OK
2021/11/13 06:31:37 INFO  : two: Copied (replaced existing)
2021/11/13 06:31:37 DEBUG : five: md5 = b36ee4e5fcdfc24d71a8bdf6b52db9f9 OK
2021/11/13 06:31:37 INFO  : five: Copied (new)
2021/11/13 06:31:37 DEBUG : Waiting for deletions to finish
    sync_test.go:992: Skip test with --checksum as no hashes supported
--- PASS: TestSyncWithUpdateOlder (12.14s)
=== RUN   TestSyncWithMaxDuration
    sync_test.go:1009: Skipping test on non local remote
--- SKIP: TestSyncWithMaxDuration (0.00s)
=== RUN   TestSyncWithTrackRenames
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1058: Can track renames: false
2021/11/13 06:31:41 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Ignoring --track-renames as the source and destination do not have a common hash
2021/11/13 06:31:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:43 DEBUG : yam: md5 = 3ef4e092b0f450191b7fa1e1ab3e5a15 OK
2021/11/13 06:31:43 INFO  : yam: Copied (new)
2021/11/13 06:31:43 DEBUG : potato: md5 = f355e8092c29eaaf70eb4543bf86f5b3 OK
2021/11/13 06:31:43 INFO  : potato: Copied (new)
2021/11/13 06:31:43 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:43 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Ignoring --track-renames as the source and destination do not have a common hash
2021/11/13 06:31:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:44 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:31:44 DEBUG : potato: Unchanged skipping
2021/11/13 06:31:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:45 DEBUG : yaml: md5 = e3ce7d7014d84ec33e5fd6aa902cbea1 OK
2021/11/13 06:31:45 INFO  : yaml: Copied (new)
2021/11/13 06:31:45 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:46 INFO  : yam: Deleted
--- PASS: TestSyncWithTrackRenames (6.86s)
=== RUN   TestParseRenamesStrategyModtime
--- PASS: TestParseRenamesStrategyModtime (0.00s)
=== RUN   TestRenamesStrategyModtime
--- PASS: TestRenamesStrategyModtime (0.00s)
=== RUN   TestSyncWithTrackRenamesStrategyModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1127: Can track renames: true
2021/11/13 06:31:48 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Making map for --track-renames
2021/11/13 06:31:48 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Finished making map for --track-renames
2021/11/13 06:31:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for renames to finish
2021/11/13 06:31:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:50 DEBUG : potato: md5 = 211cde4d66b9ea6e17501b236853c159 OK
2021/11/13 06:31:50 INFO  : potato: Copied (new)
2021/11/13 06:31:50 DEBUG : yam: md5 = e4988a09e23d79f11de9c05f2a01ba37 OK
2021/11/13 06:31:50 INFO  : yam: Copied (new)
2021/11/13 06:31:50 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:51 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Making map for --track-renames
2021/11/13 06:31:51 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:31:51 DEBUG : potato: Unchanged skipping
2021/11/13 06:31:51 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Finished making map for --track-renames
2021/11/13 06:31:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for renames to finish
2021/11/13 06:31:51 INFO  : yam: Moved (server-side) to: yaml
2021/11/13 06:31:51 INFO  : yaml: Renamed from "yam"
2021/11/13 06:31:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:51 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:51 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyModtime (5.66s)
=== RUN   TestSyncWithTrackRenamesStrategyLeaf
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1163: Can track renames: true
2021/11/13 06:31:54 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Making map for --track-renames
2021/11/13 06:31:54 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Finished making map for --track-renames
2021/11/13 06:31:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for renames to finish
2021/11/13 06:31:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:56 DEBUG : sub/yam: md5 = 02dd6ec6daaa8f9f3dc08e165c06e745 OK
2021/11/13 06:31:56 INFO  : sub/yam: Copied (new)
2021/11/13 06:31:57 DEBUG : potato: md5 = 8bb61ad1efa13c9232401f6794ca97ac OK
2021/11/13 06:31:57 INFO  : potato: Copied (new)
2021/11/13 06:31:57 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:58 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:31:58 DEBUG : potato: Unchanged skipping
2021/11/13 06:31:58 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Making map for --track-renames
2021/11/13 06:31:58 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Finished making map for --track-renames
2021/11/13 06:31:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:31:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for renames to finish
2021/11/13 06:31:59 INFO  : sub/yam: Moved (server-side) to: yam
2021/11/13 06:31:59 INFO  : yam: Renamed from "sub/yam"
2021/11/13 06:31:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:31:59 DEBUG : Waiting for deletions to finish
2021/11/13 06:31:59 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyLeaf (13.56s)
=== RUN   TestMoveWithDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:32:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:32:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:32:10 DEBUG : sub dir/hello world: md5 = ee163695995b07ef7046427d087423e8 OK
2021/11/13 06:32:10 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:32:10 INFO  : sub dir/hello world: Deleted
2021/11/13 06:32:12 DEBUG : nested/sub dir/file: md5 = e19b2ce44903d2f50ac3330a0137ca79 OK
2021/11/13 06:32:12 INFO  : nested/sub dir/file: Copied (new)
2021/11/13 06:32:12 INFO  : nested/sub dir/file: Deleted
2021/11/13 06:32:12 INFO  : sub dir: Removing directory
2021/11/13 06:32:12 INFO  : nested/sub dir: Removing directory
2021/11/13 06:32:12 INFO  : nested: Removing directory
2021/11/13 06:32:12 DEBUG : Local file system at /tmp/rclone3361733286: deleted 3 directories
2021/11/13 06:32:15 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2021/11/13 06:32:16 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2021/11/13 06:32:17 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithDeleteEmptySrcDirs (10.44s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:32:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:32:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:32:20 DEBUG : sub dir/hello world: md5 = 2e15d25d8a3c425bb6371bf4f09959cc OK
2021/11/13 06:32:20 INFO  : sub dir/hello world: Copied (new)
2021/11/13 06:32:20 INFO  : sub dir/hello world: Deleted
2021/11/13 06:32:22 DEBUG : nested/sub dir/file: md5 = 24827e029e7897e28dac708c9efcbb5a OK
2021/11/13 06:32:22 INFO  : nested/sub dir/file: Copied (new)
2021/11/13 06:32:22 INFO  : nested/sub dir/file: Deleted
2021/11/13 06:32:25 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2021/11/13 06:32:25 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2021/11/13 06:32:26 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (9.36s)
=== RUN   TestMoveWithIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:32:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:32:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:32:28 DEBUG : existing: md5 = 7dbc07ffed49a2111f9ae8881c566780 OK
2021/11/13 06:32:28 INFO  : existing: Copied (new)
2021/11/13 06:32:28 INFO  : existing: Deleted
2021/11/13 06:32:29 DEBUG : existing-b: md5 = 1a9857be0be5cee7fccff53f9570bc03 OK
2021/11/13 06:32:29 INFO  : existing-b: Copied (new)
2021/11/13 06:32:29 INFO  : existing-b: Deleted
2021/11/13 06:32:29 DEBUG : existing: Destination exists, skipping
2021/11/13 06:32:29 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set
2021/11/13 06:32:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:32:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:32:29 INFO  : There was nothing to transfer
--- PASS: TestMoveWithIgnoreExisting (4.34s)
=== RUN   TestServerSideMove
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:32:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6"
2021/11/13 06:32:31 DEBUG : Config file has changed externaly - reloading
2021/11/13 06:32:31 DEBUG : Creating backend with remote "TestDrive:crypt/l71isfjsvledmldhd897ptb1ef1kf6k3ib06inptd8gt55eg0gdh5dcn3amgm9hglfr611abga6te"
2021/11/13 06:32:34 DEBUG : potato2: md5 = c3f1ed93c03e8dc5c39c8b12286df9bb OK
2021/11/13 06:32:35 DEBUG : empty space: md5 = c1d5127b24276439bccf8284a1e3e39e OK
2021/11/13 06:32:37 DEBUG : potato3: md5 = abeca61df74a54ba436868fd608d6a6e OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3' -> Encrypted drive 'TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6'
2021/11/13 06:32:39 DEBUG : empty space: md5 = 0f1f869b4bf9a1432b9deddb9edd0d6b OK
2021/11/13 06:32:41 DEBUG : potato3: md5 = 7d716391fbd2d813dba337699b0d61f4 OK
2021/11/13 06:32:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6': Using server-side directory move
2021/11/13 06:32:41 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2021/11/13 06:32:41 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2021/11/13 06:32:41 DEBUG : empty space: Unchanged skipping
2021/11/13 06:32:41 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2021/11/13 06:32:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6': Waiting for checks to finish
2021/11/13 06:32:42 INFO  : empty space: Deleted
2021/11/13 06:32:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6': Waiting for transfers to finish
2021/11/13 06:32:42 INFO  : potato3: Deleted
2021/11/13 06:32:42 INFO  : potato2: Moved (server-side)
2021/11/13 06:32:43 INFO  : potato3: Moved (server-side)
2021/11/13 06:32:43 INFO  : There was nothing to transfer
2021/11/13 06:32:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-buvecay7tiwogus6taqewud4"
2021/11/13 06:32:43 DEBUG : Config file has changed externaly - reloading
2021/11/13 06:32:43 DEBUG : Creating backend with remote "TestDrive:crypt/e8kdd19mjib5omun91dl95qtmplsv68u4uor6cn5ugdc67dbeg7fr9njcn10eqqkneuaiei12g1ok"
2021/11/13 06:32:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-buvecay7tiwogus6taqewud4': Using server-side directory move
2021/11/13 06:32:45 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-buvecay7tiwogus6taqewud4': Server side directory move succeeded
2021/11/13 06:32:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-buvecay7tiwogus6taqewud4': Purge remote
2021/11/13 06:32:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mabaqih3ritepil5tolixad6': Purge remote
2021/11/13 06:32:48 purge failed: directory not found
--- PASS: TestServerSideMove (17.20s)
=== RUN   TestServerSideMoveWithFilter
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:32:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gelisix4hosowem8suyibey8"
2021/11/13 06:32:48 DEBUG : Creating backend with remote "TestDrive:crypt/56msd203ofk7dlkbcg90164m1rtpj9pt7f6s5ocu5s988o26ou0bgo8uvr34dl4gf7v9qg4ppnj1g"
2021/11/13 06:32:51 DEBUG : potato2: md5 = e8f80750c0e5f56d2abf88e0f654700b OK
2021/11/13 06:32:52 DEBUG : empty space: md5 = b0f9ff6df7caca761d8a6b67a9bd5c58 OK
2021/11/13 06:32:54 DEBUG : potato3: md5 = ebce1a050630077e50d49c7d349ac711 OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3' -> Encrypted drive 'TestCryptDrive:rclone-test-gelisix4hosowem8suyibey8'
2021/11/13 06:32:57 DEBUG : empty space: md5 = 6c24db757f182b4b4c2bf6a723c0de68 OK
2021/11/13 06:32:58 DEBUG : potato3: md5 = 55809162b54579aea6aa618523cdd1c7 OK
2021/11/13 06:32:59 DEBUG : empty space: Excluded from sync (and deletion)
2021/11/13 06:32:59 DEBUG : empty space: Excluded from sync (and deletion)
2021/11/13 06:32:59 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2021/11/13 06:32:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gelisix4hosowem8suyibey8': Waiting for checks to finish
2021/11/13 06:32:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gelisix4hosowem8suyibey8': Waiting for transfers to finish
2021/11/13 06:33:00 INFO  : potato3: Deleted
2021/11/13 06:33:00 INFO  : potato2: Moved (server-side)
2021/11/13 06:33:00 INFO  : potato3: Moved (server-side)
2021/11/13 06:33:00 INFO  : There was nothing to transfer
2021/11/13 06:33:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cixepoq9mofewuw1wixojub8"
2021/11/13 06:33:01 DEBUG : Creating backend with remote "TestDrive:crypt/ufah5qb4jnrkm8ehph6bd3lr5rbn0hsps0352pq3931q8fke8dg0lq71o8hm14ep11kkqd8f6588q"
2021/11/13 06:33:03 DEBUG : empty space: Excluded from sync (and deletion)
2021/11/13 06:33:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cixepoq9mofewuw1wixojub8': Waiting for checks to finish
2021/11/13 06:33:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cixepoq9mofewuw1wixojub8': Waiting for transfers to finish
2021/11/13 06:33:04 INFO  : potato2: Moved (server-side)
2021/11/13 06:33:05 INFO  : potato3: Moved (server-side)
2021/11/13 06:33:05 INFO  : There was nothing to transfer
2021/11/13 06:33:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cixepoq9mofewuw1wixojub8': Purge remote
2021/11/13 06:33:06 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:33:06 DEBUG : pacer: Rate limited, increasing sleep to 1.609598092s
2021/11/13 06:33:06 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:33:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gelisix4hosowem8suyibey8': Purge remote
--- PASS: TestServerSideMoveWithFilter (19.34s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:33:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9"
2021/11/13 06:33:08 DEBUG : Creating backend with remote "TestDrive:crypt/vkihic6miq0v3ikjcf2ovbatkgscr3ea99iecjbthit3tua97hpvlffi8f5g7hurgvjq77k3mtio2"
2021/11/13 06:33:11 DEBUG : potato2: md5 = 1301fdd59024384cca80365467e1e3ac OK
2021/11/13 06:33:12 DEBUG : empty space: md5 = 02d25db2fa876d28d11555555b920426 OK
2021/11/13 06:33:13 DEBUG : potato3: md5 = 1d2711f73506699a70b5f42703c11080 OK
2021/11/13 06:33:13 DEBUG : tomatoDir: Making directory
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3' -> Encrypted drive 'TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9'
2021/11/13 06:33:17 DEBUG : empty space: md5 = 10ee7318265261fcc8b67c956020b6d0 OK
2021/11/13 06:33:19 DEBUG : potato3: md5 = 3b7c07ba0d193cfc17438cc0d1338f74 OK
2021/11/13 06:33:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9': Using server-side directory move
2021/11/13 06:33:19 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2021/11/13 06:33:20 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2021/11/13 06:33:20 DEBUG : empty space: Unchanged skipping
2021/11/13 06:33:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9': Waiting for checks to finish
2021/11/13 06:33:20 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2021/11/13 06:33:20 INFO  : empty space: Deleted
2021/11/13 06:33:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9': Waiting for transfers to finish
2021/11/13 06:33:20 INFO  : potato3: Deleted
2021/11/13 06:33:21 INFO  : potato2: Moved (server-side)
2021/11/13 06:33:21 INFO  : potato3: Moved (server-side)
2021/11/13 06:33:21 INFO  : tomatoDir: Removing directory
2021/11/13 06:33:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': deleted 1 directories
2021/11/13 06:33:22 INFO  : There was nothing to transfer
2021/11/13 06:33:23 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cigabes6sawapom2wuyejof8"
2021/11/13 06:33:23 DEBUG : Creating backend with remote "TestDrive:crypt/pgmsfb6fbj0cfb810la4o49a3cso7ruif2dgvaedse6vgmrg5mhoje528n0cgsletuft0baabrvmi"
2021/11/13 06:33:24 DEBUG : tomatoDir: Making directory
2021/11/13 06:33:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cigabes6sawapom2wuyejof8': Using server-side directory move
2021/11/13 06:33:26 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cigabes6sawapom2wuyejof8': Server side directory move succeeded
2021/11/13 06:33:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cigabes6sawapom2wuyejof8': Purge remote
2021/11/13 06:33:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fekafun3yegovop6gebapag9': Purge remote
2021/11/13 06:33:28 purge failed: directory not found
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (21.18s)
=== RUN   TestServerSideMoveOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1399: Skipping test as remote supports DirMove
--- SKIP: TestServerSideMoveOverlap (0.48s)
=== RUN   TestSyncOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:33:29 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/rclone-sync-test"
2021/11/13 06:33:29 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0"
--- PASS: TestSyncOverlap (2.49s)
=== RUN   TestSyncCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:33:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:33:32 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:33:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/CompareDest"
2021/11/13 06:33:36 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/gveqi14airsml4bgu7krj116o8"
2021/11/13 06:33:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:33:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:33:41 DEBUG : one: md5 = a8d2814aa26f47c1e8f5bff8363261ed OK
2021/11/13 06:33:41 INFO  : one: Copied (new)
2021/11/13 06:33:41 DEBUG : Waiting for deletions to finish
2021/11/13 06:33:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:33:43 DEBUG : one: Sizes differ (src 5 vs dst 3)
2021/11/13 06:33:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:33:45 DEBUG : one: md5 = 32c2e135f83901cbeeaa499ea20a84a9 OK
2021/11/13 06:33:45 INFO  : one: Copied (replaced existing)
2021/11/13 06:33:45 DEBUG : Waiting for deletions to finish
2021/11/13 06:33:47 DEBUG : dst/one: md5 = 601ee5e0bbdeeecd85c20287616c46fe OK
2021/11/13 06:33:49 DEBUG : CompareDest/one: md5 = 64a76428990c889ccdfd4bfbb30588b8 OK
2021/11/13 06:33:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:33:51 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:33:51 DEBUG : one: Destination found in --compare-dest, skipping
2021/11/13 06:33:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:33:51 DEBUG : Waiting for deletions to finish
2021/11/13 06:33:51 INFO  : There was nothing to transfer
2021/11/13 06:33:53 DEBUG : CompareDest/two: md5 = 2d0f96bde35c9ed66e3f8b10a899f7d7 OK
2021/11/13 06:33: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)
2021/11/13 06:33:54 DEBUG : pacer: Rate limited, increasing sleep to 1.003673723s
2021/11/13 06:33:54 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:33:54 DEBUG : pacer: Rate limited, increasing sleep to 2.437148408s
2021/11/13 06:33:55 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:33:55 DEBUG : pacer: Rate limited, increasing sleep to 4.930417272s
2021/11/13 06:33:58 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:33:58 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:33:58 DEBUG : two: Destination found in --compare-dest, skipping
2021/11/13 06:33:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:34:03 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:34:03 DEBUG : one: Destination found in --compare-dest, skipping
2021/11/13 06:34:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:34:03 DEBUG : Waiting for deletions to finish
2021/11/13 06:34:03 INFO  : There was nothing to transfer
2021/11/13 06:34:04 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:34:04 DEBUG : two: Destination found in --compare-dest, skipping
2021/11/13 06:34:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:34:05 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:34:05 DEBUG : one: Destination found in --compare-dest, skipping
2021/11/13 06:34:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:34:05 DEBUG : Waiting for deletions to finish
2021/11/13 06:34:05 INFO  : There was nothing to transfer
    sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test
2021/11/13 06:34:07 DEBUG : two: Sizes differ (src 5 vs dst 3)
2021/11/13 06:34:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:34:07 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:34:07 DEBUG : one: Destination found in --compare-dest, skipping
2021/11/13 06:34:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:34:08 DEBUG : two: md5 = 3935d2f4923df91847f0a42a3733e4af OK
2021/11/13 06:34:08 INFO  : two: Copied (new)
2021/11/13 06:34:08 DEBUG : Waiting for deletions to finish
2021/11/13 06:34:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:34:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:34:14 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:34:14 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:34:14 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:34:14 DEBUG : pacer: Rate limited, increasing sleep to 1.251376598s
2021/11/13 06:34:15 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:34:15 DEBUG : pacer: Rate limited, increasing sleep to 2.126589618s
2021/11/13 06:34:16 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestSyncCompareDest (46.20s)
=== RUN   TestSyncMultipleCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:34:21 DEBUG : pre-dest1/1: md5 = 64f0179b8c9ac46a30489bd51ea41d65 OK
2021/11/13 06:34:24 DEBUG : pre-dest2/2: md5 = f1678c5465243d45a6f22a53dbab345f OK
2021/11/13 06:34:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dest"
2021/11/13 06:34:24 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/rg03c1jvnehrrc617i0lnqjddc"
2021/11/13 06:34:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:34:25 DEBUG : pacer: Rate limited, increasing sleep to 1.936492278s
2021/11/13 06:34:25 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:34:25 DEBUG : pacer: Rate limited, increasing sleep to 2.010636999s
2021/11/13 06:34:28 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:34:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/pre-dest1"
2021/11/13 06:34:30 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/bbnblvh6k061ssopqrp18kd7gc"
2021/11/13 06:34:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/pre-dest2"
2021/11/13 06:34:31 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/dgicm1h6b5ejvlltm8eeif0bnk"
2021/11/13 06:34:32 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:34:32 DEBUG : 1: Destination found in --compare-dest, skipping
2021/11/13 06:34:33 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:34:33 DEBUG : 2: Destination found in --compare-dest, skipping
2021/11/13 06:34:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dest': Waiting for checks to finish
2021/11/13 06:34:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dest': Waiting for transfers to finish
2021/11/13 06:34:36 DEBUG : 3: md5 = 064d5bba1cf71de7d64d8c3bd0fd34f0 OK
2021/11/13 06:34:36 INFO  : 3: Copied (new)
2021/11/13 06:34:36 DEBUG : Waiting for deletions to finish
2021/11/13 06:34:40 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc"
2021/11/13 06:34:41 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro"
2021/11/13 06:34:42 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg"
--- PASS: TestSyncMultipleCompareDest (24.56s)
=== RUN   TestSyncCopyDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:34:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:34:43 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:34:45 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/CopyDest"
2021/11/13 06:34:45 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/d09o6po3f7bm6ce32vdgs8h9ls"
2021/11/13 06:34:45 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:34:45 DEBUG : pacer: Rate limited, increasing sleep to 1.276191929s
2021/11/13 06:34:45 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:34:45 DEBUG : pacer: Rate limited, increasing sleep to 2.24253616s
2021/11/13 06:34:47 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:34:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:34:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:34:53 DEBUG : one: md5 = 83971b7a00f814380ced93b1d8068249 OK
2021/11/13 06:34:53 INFO  : one: Copied (new)
2021/11/13 06:34:53 DEBUG : Waiting for deletions to finish
2021/11/13 06:34:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:34:55 DEBUG : one: Sizes differ (src 5 vs dst 3)
2021/11/13 06:34:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:34:56 DEBUG : one: md5 = 3eb6df9c4b7bfd8d1af9d78028ed9727 OK
2021/11/13 06:34:56 INFO  : one: Copied (replaced existing)
2021/11/13 06:34:56 DEBUG : Waiting for deletions to finish
2021/11/13 06:34:58 DEBUG : dst/one: md5 = 9772672ff9ec73f964611fdeb807763e OK
2021/11/13 06:35:00 DEBUG : CopyDest/one: md5 = 85936a8870a32dbdb42618e694ee8776 OK
2021/11/13 06:35:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/BackupDir"
2021/11/13 06:35:01 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/s6dbk3lfi7c9kfvo6j7bla9m0g"
2021/11/13 06:35:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:35:04 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:04 DEBUG : one: Sizes differ (src 5 vs dst 3)
2021/11/13 06:35:04 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:35:04 DEBUG : pacer: Rate limited, increasing sleep to 1.685266225s
2021/11/13 06:35:05 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:35:05 DEBUG : pacer: Rate limited, increasing sleep to 2.251922525s
2021/11/13 06:35:06 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:35:10 INFO  : one: Moved (server-side)
2021/11/13 06:35:11 INFO  : one: Copied (server-side copy)
2021/11/13 06:35:11 DEBUG : one: Destination found in --copy-dest, using server-side copy
2021/11/13 06:35:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:35:11 DEBUG : Waiting for deletions to finish
2021/11/13 06:35:13 DEBUG : CopyDest/two: md5 = 620d29063c8f7ca85e07be49925cd8df OK
2021/11/13 06:35:14 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:16 INFO  : two: Copied (server-side copy)
2021/11/13 06:35:16 DEBUG : two: Destination found in --copy-dest, using server-side copy
2021/11/13 06:35:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:35:16 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:16 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:16 DEBUG : one: Unchanged skipping
2021/11/13 06:35:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:35:16 DEBUG : Waiting for deletions to finish
2021/11/13 06:35:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:35:18 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:18 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:18 DEBUG : one: Unchanged skipping
2021/11/13 06:35:18 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:18 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:18 DEBUG : two: Unchanged skipping
2021/11/13 06:35:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:35:18 DEBUG : Waiting for deletions to finish
2021/11/13 06:35:18 INFO  : There was nothing to transfer
2021/11/13 06:35:20 DEBUG : CopyDest/three: md5 = d842d6d523567809bcf81067e8663c0a OK
2021/11/13 06:35:21 DEBUG : three: Sizes differ (src 7 vs dst 5)
2021/11/13 06:35:21 DEBUG : three: Destination not found in --copy-dest
2021/11/13 06:35:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:35:21 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:21 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:21 DEBUG : one: Unchanged skipping
2021/11/13 06:35:21 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:21 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2021/11/13 06:35:21 DEBUG : two: Unchanged skipping
2021/11/13 06:35:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:35:23 DEBUG : three: md5 = 0892592735c151fa48f13a236b745cb5 OK
2021/11/13 06:35:23 INFO  : three: Copied (new)
2021/11/13 06:35:23 DEBUG : Waiting for deletions to finish
2021/11/13 06:35:24 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:35:24 DEBUG : pacer: Rate limited, increasing sleep to 1.388299073s
2021/11/13 06:35:25 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:35:25 DEBUG : pacer: Rate limited, increasing sleep to 2.898807361s
2021/11/13 06:35:26 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:35:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2021/11/13 06:35:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:35:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:35:34 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:35:34 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:35:34 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2021/11/13 06:35:35 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
--- PASS: TestSyncCopyDest (53.66s)
=== RUN   TestSyncBackupDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:35:39 DEBUG : dst/one: md5 = 12fb87f0a72e50d6157e81ae584ebbaa OK
2021/11/13 06:35:40 DEBUG : dst/two: md5 = 91326999669da65f1b8166f1a94daa5a OK
2021/11/13 06:35:42 DEBUG : dst/three.txt: md5 = d21e9a951c53b7a7611b5a589e070a88 OK
2021/11/13 06:35:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:35:43 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:35:44 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/backup"
2021/11/13 06:35:44 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/1nrff024r7pq65ecp72fc28jb0"
2021/11/13 06:35:46 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/11/13 06:35:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:35:46 DEBUG : two: Unchanged skipping
2021/11/13 06:35:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:35:48 INFO  : one: Moved (server-side)
2021/11/13 06:35:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:35:49 DEBUG : one: md5 = 2695353057b966f3b06503496459101a OK
2021/11/13 06:35:49 INFO  : one: Copied (new)
2021/11/13 06:35:49 DEBUG : Waiting for deletions to finish
2021/11/13 06:35:51 INFO  : three.txt: Moved (server-side)
2021/11/13 06:35:51 INFO  : three.txt: Moved into backup dir
2021/11/13 06:35:53 DEBUG : dst/three.txt: md5 = eaa7bc29f454fa9decf81b11a44cf38e OK
2021/11/13 06:35:54 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/11/13 06:35:54 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:35:54 DEBUG : two: Unchanged skipping
2021/11/13 06:35:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:35:54 INFO  : one: Deleted
2021/11/13 06:35:55 INFO  : one: Moved (server-side)
2021/11/13 06:35:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:35:57 DEBUG : one: md5 = da8023e20f3963dca5995e87164195db OK
2021/11/13 06:35:57 INFO  : one: Copied (new)
2021/11/13 06:35:57 DEBUG : Waiting for deletions to finish
2021/11/13 06:35:58 INFO  : three.txt: Deleted
2021/11/13 06:35:59 INFO  : three.txt: Moved (server-side)
2021/11/13 06:35:59 INFO  : three.txt: Moved into backup dir
2021/11/13 06:36:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:36:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:36:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:36:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2021/11/13 06:36:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:36:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
--- PASS: TestSyncBackupDir (28.40s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:36:07 DEBUG : dst/one: md5 = 04f71cc20803d2926d52bd8e250e21e2 OK
2021/11/13 06:36:08 DEBUG : dst/two: md5 = 3882d317885c6279ea65725e4c44fa07 OK
2021/11/13 06:36:10 DEBUG : dst/three.txt: md5 = 9a86a883d635f92fef0e9a59f262d69e OK
2021/11/13 06:36:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:36:11 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:36:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/backup"
2021/11/13 06:36:12 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/1nrff024r7pq65ecp72fc28jb0"
2021/11/13 06:36:14 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/11/13 06:36:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:36:14 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:36:14 DEBUG : two: Unchanged skipping
2021/11/13 06:36:16 INFO  : one: Moved (server-side) to: one.bak
2021/11/13 06:36:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:36:17 DEBUG : one: md5 = 9741b3a3c290d980577659e600f3f4d6 OK
2021/11/13 06:36:17 INFO  : one: Copied (new)
2021/11/13 06:36:17 DEBUG : Waiting for deletions to finish
2021/11/13 06:36:18 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/11/13 06:36:18 INFO  : three.txt: Moved into backup dir
2021/11/13 06:36:20 DEBUG : dst/three.txt: md5 = ee827c186a5847665d14ce894d77a78b OK
2021/11/13 06:36:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:36:21 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/11/13 06:36:21 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:36:21 DEBUG : two: Unchanged skipping
2021/11/13 06:36:22 INFO  : one.bak: Deleted
2021/11/13 06:36:23 INFO  : one: Moved (server-side) to: one.bak
2021/11/13 06:36:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:36:24 DEBUG : one: md5 = 1f0493e758cd72cf70bff47527bb6ce3 OK
2021/11/13 06:36:24 INFO  : one: Copied (new)
2021/11/13 06:36:24 DEBUG : Waiting for deletions to finish
2021/11/13 06:36:25 INFO  : three.txt.bak: Deleted
2021/11/13 06:36:25 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/11/13 06:36:25 INFO  : three.txt: Moved into backup dir
2021/11/13 06:36:30 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:36:30 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:36:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2021/11/13 06:36:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2021/11/13 06:36:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2021/11/13 06:36:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
--- PASS: TestSyncBackupDirWithSuffix (26.92s)
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:36:34 DEBUG : dst/one: md5 = d9171d51664fbbe25f080b0e2e93830e OK
2021/11/13 06:36:36 DEBUG : dst/two: md5 = c6cf2c6823a63af65503fb8b75588c70 OK
2021/11/13 06:36:37 DEBUG : dst/three.txt: md5 = 1cb2f7bb7a416b5ff179cb6be8204d5e OK
2021/11/13 06:36:38 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:36:38 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:36:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/backup"
2021/11/13 06:36:39 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/1nrff024r7pq65ecp72fc28jb0"
2021/11/13 06:36:40 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/11/13 06:36:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:36:40 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:36:40 DEBUG : two: Unchanged skipping
2021/11/13 06:36:42 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/11/13 06:36:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:36:44 DEBUG : one: md5 = 8661b37ac39df7023c9ee2805ad6a91f OK
2021/11/13 06:36:44 INFO  : one: Copied (new)
2021/11/13 06:36:44 DEBUG : Waiting for deletions to finish
2021/11/13 06:36:45 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/11/13 06:36:45 INFO  : three.txt: Moved into backup dir
2021/11/13 06:36:47 DEBUG : dst/three.txt: md5 = c403dba259f6a62fc02ba18ca8ef7130 OK
2021/11/13 06:36:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:36:48 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/11/13 06:36:48 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:36:48 DEBUG : two: Unchanged skipping
2021/11/13 06:36:49 INFO  : one-2019-01-01: Deleted
2021/11/13 06:36:49 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/11/13 06:36:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:36:51 DEBUG : one: md5 = 55a069b31b92a031e857afa03531e3f6 OK
2021/11/13 06:36:51 INFO  : one: Copied (new)
2021/11/13 06:36:51 DEBUG : Waiting for deletions to finish
2021/11/13 06:36:52 INFO  : three-2019-01-01.txt: Deleted
2021/11/13 06:36:53 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/11/13 06:36:53 INFO  : three.txt: Moved into backup dir
2021/11/13 06:36:57 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:36:57 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:36:58 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2021/11/13 06:36:58 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2021/11/13 06:36:58 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2021/11/13 06:36:58 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (26.85s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:37:01 DEBUG : dst/one: md5 = f53ddd8d7f4e545ed965a980d133a09b OK
2021/11/13 06:37:02 DEBUG : dst/two: md5 = 603eef0a8ddb537167cb955a1a8aba8e OK
2021/11/13 06:37:04 DEBUG : dst/three.txt: md5 = b08aa35d45e4ef3d0fa36a220aa82adc OK
2021/11/13 06:37:05 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:37:05 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:37:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:37:06 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:37:06 DEBUG : two: Unchanged skipping
2021/11/13 06:37:06 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/11/13 06:37:07 INFO  : one: Moved (server-side) to: one.bak
2021/11/13 06:37:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:37:08 DEBUG : one: md5 = 739374a5fcbf9abcaa7e5d4218e19d02 OK
2021/11/13 06:37:08 INFO  : one: Copied (new)
2021/11/13 06:37:08 DEBUG : Waiting for deletions to finish
2021/11/13 06:37:09 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/11/13 06:37:09 INFO  : three.txt: Moved into backup dir
2021/11/13 06:37:11 DEBUG : dst/three.txt: md5 = e56fc47cc04c359f7dd7013c9f03364d OK
2021/11/13 06:37:12 DEBUG : three.txt.bak: Excluded from sync (and deletion)
2021/11/13 06:37:12 DEBUG : one.bak: Excluded from sync (and deletion)
2021/11/13 06:37:12 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/11/13 06:37:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for checks to finish
2021/11/13 06:37:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:37:12 DEBUG : two: Unchanged skipping
2021/11/13 06:37:13 INFO  : one.bak: Deleted
2021/11/13 06:37:13 INFO  : one: Moved (server-side) to: one.bak
2021/11/13 06:37:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst': Waiting for transfers to finish
2021/11/13 06:37:15 DEBUG : one: md5 = 2c24dc51c92f0e9a3d50a26f6d7b1855 OK
2021/11/13 06:37:15 INFO  : one: Copied (new)
2021/11/13 06:37:15 DEBUG : Waiting for deletions to finish
2021/11/13 06:37:16 INFO  : three.txt.bak: Deleted
2021/11/13 06:37:16 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/11/13 06:37:16 INFO  : three.txt: Moved into backup dir
2021/11/13 06:37:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:37:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2021/11/13 06:37:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2021/11/13 06:37:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2021/11/13 06:37:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2021/11/13 06:37:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
--- PASS: TestSyncBackupDirSuffixOnly (22.89s)
=== RUN   TestSyncSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:37:24 DEBUG : dst/one: md5 = 6b6e65b254803f890a54af5f2a6a9ed6 OK
2021/11/13 06:37:25 DEBUG : dst/two: md5 = 8a05c0673615cc6bb42f9a09b78d8a69 OK
2021/11/13 06:37:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:37:25 DEBUG : pacer: Rate limited, increasing sleep to 1.866933592s
2021/11/13 06:37:26 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:37:29 DEBUG : dst/three.txt: md5 = 5f8b458577f95a57b437810a4e09ce82 OK
2021/11/13 06:37:29 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:37:29 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:37:30 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/11/13 06:37:31 INFO  : one: Moved (server-side) to: one.bak
2021/11/13 06:37:33 DEBUG : one: md5 = 07985fa6792bbc004da7d958f49f32c3 OK
2021/11/13 06:37:33 INFO  : one: Copied (new)
2021/11/13 06:37:34 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:37:34 DEBUG : two: Unchanged skipping
2021/11/13 06:37:34 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2021/11/13 06:37:35 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/11/13 06:37:36 DEBUG : three.txt: md5 = 6ebe24de628cb1313c7efd7a4b7b52fb OK
2021/11/13 06:37:36 INFO  : three.txt: Copied (new)
2021/11/13 06:37:38 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/11/13 06:37:39 INFO  : one.bak: Deleted
2021/11/13 06:37:39 INFO  : one: Moved (server-side) to: one.bak
2021/11/13 06:37:41 DEBUG : one: md5 = c19c7e7098f0549d2e09399aa2a308b7 OK
2021/11/13 06:37:41 INFO  : one: Copied (new)
2021/11/13 06:37:41 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:37:41 DEBUG : two: Unchanged skipping
2021/11/13 06:37:41 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2021/11/13 06:37:42 INFO  : three.txt.bak: Deleted
2021/11/13 06:37:43 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/11/13 06:37:44 DEBUG : three.txt: md5 = 77572369acaabf2aa8f485c8be08ea04 OK
2021/11/13 06:37:44 INFO  : three.txt: Copied (new)
2021/11/13 06:37:45 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:37:45 DEBUG : pacer: Rate limited, increasing sleep to 1.819273451s
2021/11/13 06:37:45 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:37:45 DEBUG : pacer: Rate limited, increasing sleep to 2.908672259s
2021/11/13 06:37:47 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2021/11/13 06:37:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncSuffix (33.47s)
=== RUN   TestSyncSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:37:57 DEBUG : dst/one: md5 = f11a033201caf21e413a11f24b2d0927 OK
2021/11/13 06:37:59 DEBUG : dst/two: md5 = a15c806a5274dc9d3e73ed97018bddfe OK
2021/11/13 06:38:00 DEBUG : dst/three.txt: md5 = e596514348de4747cfca92ffa77a1117 OK
2021/11/13 06:38:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3/dst"
2021/11/13 06:38:01 DEBUG : Creating backend with remote "TestDrive:crypt/npkh3kflmgnkmb832b2gbjjgdga4viq82bi6jg9v0cq728h2qsh6l4d6r32o1khsvb9jfhgsr0mc0/31u3jie661vd5p8j7rtc3hgbh0"
2021/11/13 06:38:02 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/11/13 06:38:03 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/11/13 06:38:03 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:38:03 DEBUG : pacer: Rate limited, increasing sleep to 1.065996796s
2021/11/13 06:38:04 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:38:04 DEBUG : pacer: Rate limited, increasing sleep to 2.011149637s
2021/11/13 06:38:05 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:38:05 DEBUG : pacer: Rate limited, increasing sleep to 4.046961554s
2021/11/13 06:38:07 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:38:12 DEBUG : one: md5 = fca7c60fbf21e82510b583a22a8b2b36 OK
2021/11/13 06:38:12 INFO  : one: Copied (new)
2021/11/13 06:38:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:38:12 DEBUG : two: Unchanged skipping
2021/11/13 06:38:12 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2021/11/13 06:38:13 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/11/13 06:38:15 DEBUG : three.txt: md5 = 3d0d716c95fddf310abb3543930370af OK
2021/11/13 06:38:15 INFO  : three.txt: Copied (new)
2021/11/13 06:38:16 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/11/13 06:38:17 INFO  : one-2019-01-01: Deleted
2021/11/13 06:38:17 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/11/13 06:38:19 DEBUG : one: md5 = a0a91744466461c4f42a9f7093dd1aca OK
2021/11/13 06:38:19 INFO  : one: Copied (new)
2021/11/13 06:38:19 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:38:19 DEBUG : two: Unchanged skipping
2021/11/13 06:38:20 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2021/11/13 06:38:21 INFO  : three-2019-01-01.txt: Deleted
2021/11/13 06:38:21 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/11/13 06:38:23 DEBUG : three.txt: md5 = 00ecc3eb98cccac0af3d2a50f567e3b3 OK
2021/11/13 06:38:23 INFO  : three.txt: Copied (new)
2021/11/13 06:38:24 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:38:24 DEBUG : pacer: Rate limited, increasing sleep to 1.855887331s
2021/11/13 06:38:24 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:38:24 DEBUG : pacer: Rate limited, increasing sleep to 2.985631002s
2021/11/13 06:38:27 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2021/11/13 06:38:32 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncSuffixKeepExtension (37.81s)
=== RUN   TestSyncUTFNorm
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:38:34 DEBUG : Testêé: md5 = d131f7d5fdcc180f1a5682e7607e2eaa OK
2021/11/13 06:38:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:38:35 DEBUG : Testêé: Sizes differ (src 14 vs dst 18)
2021/11/13 06:38:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:38:36 DEBUG : Testêé: md5 = a4f75a9e94f404fcc549f72520fccea6 OK
2021/11/13 06:38:36 INFO  : Testêé: Copied (replaced existing)
2021/11/13 06:38:36 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncUTFNorm (4.72s)
=== RUN   TestSyncImmutable
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:38:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:38:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:38:40 DEBUG : existing: md5 = 903ace494359a403f3b8a3b9472f39d7 OK
2021/11/13 06:38:40 INFO  : existing: Copied (new)
2021/11/13 06:38:40 DEBUG : Waiting for deletions to finish
2021/11/13 06:38:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:38:41 DEBUG : existing: Sizes differ (src 8 vs dst 6)
2021/11/13 06:38:41 ERROR : existing: Source and destination exist but do not match: immutable file modified
2021/11/13 06:38:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:38:41 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': not deleting files as there were IO errors
2021/11/13 06:38:41 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': not deleting directories as there were IO errors
--- PASS: TestSyncImmutable (4.66s)
=== RUN   TestSyncIgnoreCase
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:38:44 DEBUG : EXISTING: md5 = b859a75bec4eae9ad5aefc8b59d6298a OK
2021/11/13 06:38: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)
2021/11/13 06:38:44 DEBUG : pacer: Rate limited, increasing sleep to 1.632524633s
2021/11/13 06:38:44 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:38:44 DEBUG : pacer: Rate limited, increasing sleep to 2.089327703s
2021/11/13 06:38:46 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:38:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:38:48 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:38:48 DEBUG : existing: Unchanged skipping
2021/11/13 06:38:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:38:48 DEBUG : Waiting for deletions to finish
2021/11/13 06:38:48 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreCase (7.40s)
=== RUN   TestMaxTransfer
=== RUN   TestMaxTransfer/Hard
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1989: This test only runs on local
=== RUN   TestMaxTransfer/Soft
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1989: This test only runs on local
=== RUN   TestMaxTransfer/Cautious
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
    sync_test.go:1989: This test only runs on local
--- PASS: TestMaxTransfer (1.64s)
    --- SKIP: TestMaxTransfer/Hard (0.54s)
    --- SKIP: TestMaxTransfer/Soft (0.54s)
    --- SKIP: TestMaxTransfer/Cautious (0.56s)
=== RUN   TestSyncConcurrentDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:38:53 DEBUG : both0: md5 = de7c5405859611cfcf8bb484d18d7bff OK
2021/11/13 06:38:54 DEBUG : only0: md5 = d8833034b350b7364f065a119966eacd OK
2021/11/13 06:38:56 DEBUG : both1: md5 = 6e68cbffc2e8ba2a10c9916789973f02 OK
2021/11/13 06:38:57 DEBUG : only1: md5 = 0bae737d8d7bc6c611be088343237b25 OK
2021/11/13 06:38:59 DEBUG : both2: md5 = dd439498d0f9281e1c62e0933d906bf2 OK
2021/11/13 06:39:00 DEBUG : only2: md5 = b67b890113646913962e0ca8f4893f84 OK
2021/11/13 06:39:02 DEBUG : both3: md5 = 711c252f5fb1041bcff9c7a84919e46e OK
2021/11/13 06:39:03 DEBUG : only3: md5 = 15b42285d9ddc91e1cffafa436da1fcd OK
2021/11/13 06:39:05 DEBUG : both4: md5 = 4ded1f162ff89fd2c08b772c0e6cbff8 OK
2021/11/13 06:39:06 DEBUG : only4: md5 = 5a1ca21172ff05e7381c5bf2df251272 OK
2021/11/13 06:39:08 DEBUG : both5: md5 = 1183fe2490a29cbee660d5116a65b72d OK
2021/11/13 06:39:10 DEBUG : only5: md5 = 82ab05ec3870ac35c08efbde76d1444a OK
2021/11/13 06:39:11 DEBUG : both6: md5 = 9f2a0d3288942eb4b763b0974b523d28 OK
2021/11/13 06:39:13 DEBUG : only6: md5 = eb57d5573c116884dbd330137928b402 OK
2021/11/13 06:39:13 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:39:13 DEBUG : pacer: Rate limited, increasing sleep to 1.109631861s
2021/11/13 06:39:13 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:39:13 DEBUG : pacer: Rate limited, increasing sleep to 2.347823491s
2021/11/13 06:39:14 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:39:14 DEBUG : pacer: Rate limited, increasing sleep to 4.040237697s
2021/11/13 06:39:17 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:39:22 DEBUG : both7: md5 = 9cac01ff11d2068c137fd3de196768b8 OK
2021/11/13 06:39:23 DEBUG : only7: md5 = 7ff31636bdef22ea5abc1cc2b529b334 OK
2021/11/13 06:39:25 DEBUG : both8: md5 = f9c3cecf7b195bec4395c8a7055ed244 OK
2021/11/13 06:39:26 DEBUG : only8: md5 = 5956c75b04ad5f03ca91b594e9185f97 OK
2021/11/13 06:39:28 DEBUG : both9: md5 = 9adeda24c385ff01df3191d34246dc81 OK
2021/11/13 06:39:30 DEBUG : only9: md5 = f9f8fdd6b22fad8d9c37f04f7a40b460 OK
2021/11/13 06:39:31 DEBUG : both10: md5 = 9d2573071744849c779b74ab0419804b OK
2021/11/13 06:39:33 DEBUG : only10: md5 = 7bb4d8d752518f2f6ac1f50991a273df OK
2021/11/13 06:39:33 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:39:33 DEBUG : pacer: Rate limited, increasing sleep to 1.896615044s
    run.go:283: Retry Put of "both11" to Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:39: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)
2021/11/13 06:39:35 DEBUG : pacer: Rate limited, increasing sleep to 2.248540081s
2021/11/13 06:39:37 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:39:40 DEBUG : both11: md5 = 26a639f656d858eeecd950d74f0db348 OK
2021/11/13 06:39:42 DEBUG : only11: md5 = 203b44eb9d23c6ed13e6c3567e10bab0 OK
2021/11/13 06:39:44 DEBUG : both12: md5 = 24b06dc326362139520bec8978a02f53 OK
2021/11/13 06:39:45 DEBUG : only12: md5 = b7708b89b445e842bc3671edc37563bc OK
2021/11/13 06:39:47 DEBUG : both13: md5 = 526a28b6251e763a30197be5154d19ed OK
2021/11/13 06:39:48 DEBUG : only13: md5 = d559afe39bab8b362f2d01a8417692bc OK
2021/11/13 06:39:50 DEBUG : both14: md5 = 2c59de891778354f0fb375fc953b99d7 OK
2021/11/13 06:39:51 DEBUG : only14: md5 = 8175ec4063e047b406f8bff5f4cec083 OK
2021/11/13 06:39:53 DEBUG : both15: md5 = 66c01eb43386d42c05088f416b93549c OK
2021/11/13 06:39:54 DEBUG : only15: md5 = a088a9600f77a12a80f1f585b4306836 OK
2021/11/13 06:39:56 DEBUG : both16: md5 = 801a02037eec7c9bf1c2a04d96f2a390 OK
2021/11/13 06:39:57 DEBUG : only16: md5 = fa3840d3956389f0de7a8161f80ecc13 OK
2021/11/13 06:39:58 DEBUG : both17: md5 = 2500630a1481c502cdcf831c4a5d8d1c OK
2021/11/13 06:40:00 DEBUG : only17: md5 = cd01ecc5f032799f98f9aa15f5abfe39 OK
2021/11/13 06:40:01 DEBUG : both18: md5 = ce6d31c620d489103c2959e52c7b472e OK
2021/11/13 06:40:03 DEBUG : only18: md5 = e571e323a2f0521e9f3e31a0eddbe914 OK
2021/11/13 06:40:04 DEBUG : both19: md5 = 4c7ec72f31e30c262143c55cba616883 OK
2021/11/13 06:40:06 DEBUG : only19: md5 = 6a20a525b7cec852f1dae846939e309f OK
2021/11/13 06:40:07 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both0: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both11: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:40:07 DEBUG : both10: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both12: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both15: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both16: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both17: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both18: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both19: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both2: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both3: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both4: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both5: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both6: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both7: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both8: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both9: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both14: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both13: Unchanged skipping
2021/11/13 06:40:07 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:40:07 DEBUG : both1: Unchanged skipping
2021/11/13 06:40:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:40:07 DEBUG : Waiting for deletions to finish
2021/11/13 06:40:07 INFO  : only2: Deleted
2021/11/13 06:40:07 INFO  : only16: Deleted
2021/11/13 06:40:07 INFO  : only8: Deleted
2021/11/13 06:40:07 INFO  : only19: Deleted
2021/11/13 06:40:08 INFO  : only1: Deleted
2021/11/13 06:40:08 INFO  : only4: Deleted
2021/11/13 06:40:08 INFO  : only14: Deleted
2021/11/13 06:40:08 INFO  : only10: Deleted
2021/11/13 06:40:08 INFO  : only3: Deleted
2021/11/13 06:40:08 INFO  : only5: Deleted
2021/11/13 06:40:08 INFO  : only17: Deleted
2021/11/13 06:40:09 INFO  : only7: Deleted
2021/11/13 06:40:09 INFO  : only0: Deleted
2021/11/13 06:40:09 INFO  : only12: Deleted
2021/11/13 06:40:09 INFO  : only13: Deleted
2021/11/13 06:40:09 INFO  : only15: Deleted
2021/11/13 06:40:10 INFO  : only18: Deleted
2021/11/13 06:40:10 INFO  : only6: Deleted
2021/11/13 06:40:10 INFO  : only9: Deleted
2021/11/13 06:40:10 INFO  : only11: Deleted
2021/11/13 06:40:10 INFO  : There was nothing to transfer
2021/11/13 06:40:15 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:40:15 DEBUG : pacer: Rate limited, increasing sleep to 1.615335604s
2021/11/13 06:40:16 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:40:16 DEBUG : pacer: Rate limited, increasing sleep to 2.149509462s
2021/11/13 06:40:18 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestSyncConcurrentDelete (95.49s)
=== RUN   TestSyncConcurrentTruncate
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3'", Local "Local file system at /tmp/rclone3361733286", Modify Window "1ms"
2021/11/13 06:40:28 DEBUG : both0: md5 = f108ac43740bb6c3612deb66728f30eb OK
2021/11/13 06:40:29 DEBUG : only0: md5 = 583e23393a027d89ed42bdbdcbfb0683 OK
2021/11/13 06:40:31 DEBUG : both1: md5 = d4205d20e68923beea1f775e7751baaa OK
2021/11/13 06:40:33 DEBUG : only1: md5 = bcde6caf9fd67aeecacda4bcd5293ced OK
2021/11/13 06:40:34 DEBUG : both2: md5 = ea08edc97178c478c1476220026397a5 OK
2021/11/13 06:40:36 DEBUG : only2: md5 = 819a8bda8abbc6f1c0350e5ad51d0fb5 OK
2021/11/13 06:40:37 DEBUG : both3: md5 = a4d1932e035ca4965077feb6a57c908f OK
2021/11/13 06:40:39 DEBUG : only3: md5 = d1fbd1ce310af2d56cab2e4cacd0504e OK
2021/11/13 06:40:40 DEBUG : both4: md5 = 807bf22e8488fd099be11f7ad85fabb2 OK
2021/11/13 06:40:42 DEBUG : only4: md5 = 0212ec2a40d95397ed3a83dc4dca1038 OK
2021/11/13 06:40:44 DEBUG : both5: md5 = 968ae1c8b8546f37520ae7e71a2a69b6 OK
2021/11/13 06:40:45 DEBUG : only5: md5 = 1efa6b34fe7832f8809dd75faac56d4e OK
2021/11/13 06:40:47 DEBUG : both6: md5 = ee370b315a5c96aaa85d8aec263dc89d OK
2021/11/13 06:40:48 DEBUG : only6: md5 = cccf512e2207dae147708f0f7070fd83 OK
2021/11/13 06:40:50 DEBUG : both7: md5 = 9156c44bb7134543dee284e12117bd6d OK
2021/11/13 06:40:52 DEBUG : only7: md5 = 0caa69a9e43b2cc5473361c5d0d1fbf0 OK
2021/11/13 06:40:53 DEBUG : both8: md5 = 0051fb3d361c985d972fb7004f595502 OK
2021/11/13 06:40:55 DEBUG : only8: md5 = 50e02ebc13645a75f4634e64c2f29c29 OK
2021/11/13 06:40:56 DEBUG : both9: md5 = 44ca6be1151f036b3a946b7776847a55 OK
2021/11/13 06:40:58 DEBUG : only9: md5 = e2710fd82715d7824fe2dc0e1a414b36 OK
2021/11/13 06:40:59 DEBUG : both10: md5 = 8a2b901c8ec01a859a4ceaa305a9283d OK
2021/11/13 06:41:01 DEBUG : only10: md5 = 21dfc780ddca8fd9290e5d0e29952f47 OK
2021/11/13 06:41:02 DEBUG : both11: md5 = 0f5d941e5bf2d38a2f3711db8d7bbf21 OK
2021/11/13 06:41:04 DEBUG : only11: md5 = ea3ce4ff1094239cc2da9a4c78e31741 OK
2021/11/13 06:41:05 DEBUG : both12: md5 = e6435d8c38f2280eda58400c3374b899 OK
2021/11/13 06:41:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:41:05 DEBUG : pacer: Rate limited, increasing sleep to 1.405047862s
2021/11/13 06:41:06 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:41:08 DEBUG : only12: md5 = 00c299e0ac10ee441d95320f88f0df9a OK
2021/11/13 06:41:10 DEBUG : both13: md5 = 6dc39ceb679e1de08c4651b5ede5f5e5 OK
2021/11/13 06:41:11 DEBUG : only13: md5 = 04cfe5f1d2f933c74b4fcbf64b509356 OK
2021/11/13 06:41:13 DEBUG : both14: md5 = 899698284e396b27de1e3137b5fade2f OK
2021/11/13 06:41:14 DEBUG : only14: md5 = 12ba225daeaf288f76c93fccb6608f09 OK
2021/11/13 06:41:16 DEBUG : both15: md5 = 320d30d05083764bc3b864515e7f520e OK
2021/11/13 06:41:17 DEBUG : only15: md5 = 1db9c0bd8d6f4873b9a48f0cf7efc7d5 OK
2021/11/13 06:41:19 DEBUG : both16: md5 = 08c0b9dda3211d84d1074beb27785060 OK
2021/11/13 06:41:20 DEBUG : only16: md5 = e8c9965e85286ebf50eaeec1d1b59aee OK
2021/11/13 06:41:22 DEBUG : both17: md5 = 66a026dd661c667934ff8beb60a74a98 OK
2021/11/13 06:41:23 DEBUG : only17: md5 = ba7da9b0639219480e573dc9cee10cd6 OK
2021/11/13 06:41:24 DEBUG : both18: md5 = 7052ead58b31f28038a0b82215017124 OK
2021/11/13 06:41:26 DEBUG : only18: md5 = 6a3ff57bfae2aed9dd5d71603bba5dbc OK
2021/11/13 06:41:27 DEBUG : both19: md5 = f61af1c057c53934f0c5fc7cb0c90069 OK
2021/11/13 06:41:29 DEBUG : only19: md5 = 02e9ebefa1135bdb39fd30ceb697c75e OK
2021/11/13 06:41:29 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both0: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both1: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both10: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both11: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both12: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both13: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both14: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both15: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both16: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both17: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both18: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both19: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both2: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both3: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both4: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both5: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both6: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both7: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both8: Unchanged skipping
2021/11/13 06:41:29 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2021/11/13 06:41:29 DEBUG : both9: Unchanged skipping
2021/11/13 06:41:29 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2021/11/13 06:41:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for checks to finish
2021/11/13 06:41:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Waiting for transfers to finish
2021/11/13 06:41:30 DEBUG : only10: md5 = c58e57f68b09efdb333f08b1d61679dc OK
2021/11/13 06:41:30 INFO  : only10: Copied (replaced existing)
2021/11/13 06:41:31 DEBUG : only1: md5 = 91f03eec1a16874898da208a7ba4e3d4 OK
2021/11/13 06:41:31 INFO  : only1: Copied (replaced existing)
2021/11/13 06:41:31 DEBUG : only11: md5 = 2eb4e60acff27160a0e8f1c087537221 OK
2021/11/13 06:41:31 INFO  : only11: Copied (replaced existing)
2021/11/13 06:41:31 DEBUG : only0: md5 = 3c9824bcd130677a74caf3728dcd9f3a OK
2021/11/13 06:41:31 INFO  : only0: Copied (replaced existing)
2021/11/13 06:41:32 DEBUG : only12: md5 = f0e1e33480e249d280534462c3fae0a4 OK
2021/11/13 06:41:32 INFO  : only12: Copied (replaced existing)
2021/11/13 06:41:32 DEBUG : only13: md5 = e16c6905fd5ba4d054870a40a113b319 OK
2021/11/13 06:41:32 INFO  : only13: Copied (replaced existing)
2021/11/13 06:41:32 DEBUG : only15: md5 = c777ac5f74c5dac037669ac86b3d0441 OK
2021/11/13 06:41:32 INFO  : only15: Copied (replaced existing)
2021/11/13 06:41:32 DEBUG : only14: md5 = 75878ebd0fe7ce743748baa71d972dbb OK
2021/11/13 06:41:32 INFO  : only14: Copied (replaced existing)
2021/11/13 06:41:33 DEBUG : only16: md5 = d3fb8ba1282463193df4b84ac0fab4c0 OK
2021/11/13 06:41:33 INFO  : only16: Copied (replaced existing)
2021/11/13 06:41:33 DEBUG : only17: md5 = 254144dcc037d529fb8331b9d2d32a0c OK
2021/11/13 06:41:33 INFO  : only17: Copied (replaced existing)
2021/11/13 06:41:33 DEBUG : only18: md5 = 060945b388114b4b510d55c4485b9674 OK
2021/11/13 06:41:33 INFO  : only18: Copied (replaced existing)
2021/11/13 06:41:33 DEBUG : only19: md5 = 2ef3b80ed15602cccc6525c3902d06d1 OK
2021/11/13 06:41:33 INFO  : only19: Copied (replaced existing)
2021/11/13 06:41:34 DEBUG : only2: md5 = 5c01854ad5a921b879d66f6532b7e475 OK
2021/11/13 06:41:34 INFO  : only2: Copied (replaced existing)
2021/11/13 06:41:34 DEBUG : only3: md5 = 1ff6d0c10e109a2ba083750cf3c06d6d OK
2021/11/13 06:41:34 INFO  : only3: Copied (replaced existing)
2021/11/13 06:41:34 DEBUG : only5: md5 = a41c07cbf97f02f915d54938c850d9ff OK
2021/11/13 06:41:34 INFO  : only5: Copied (replaced existing)
2021/11/13 06:41:34 DEBUG : only4: md5 = ded9049e848edc5cffc65d51f800c4f0 OK
2021/11/13 06:41:34 INFO  : only4: Copied (replaced existing)
2021/11/13 06:41:34 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:41:34 DEBUG : pacer: Rate limited, increasing sleep to 1.159747187s
2021/11/13 06:41:34 DEBUG : only8: 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
2021/11/13 06:41:35 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2021/11/13 06:41:35 DEBUG : pacer: Rate limited, increasing sleep to 2.497706758s
2021/11/13 06:41:35 DEBUG : only9: 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
2021/11/13 06:41:35 DEBUG : pacer: Reducing sleep to 0s
2021/11/13 06:41:35 DEBUG : only6: md5 = b0dadd17da1ee090453ed99108a9359c OK
2021/11/13 06:41:35 INFO  : only6: Copied (replaced existing)
2021/11/13 06:41:35 DEBUG : only7: md5 = 2250897beef9ea665cf69c124c8c62eb OK
2021/11/13 06:41:35 INFO  : only7: Copied (replaced existing)
2021/11/13 06:41:36 DEBUG : only8: md5 = e778c192cdaf7c68ac7e79bcce85335d OK
2021/11/13 06:41:36 INFO  : only8: Copied (replaced existing)
2021/11/13 06:41:37 DEBUG : only9: md5 = 246920bc4b8df908f2aeba749513f6a1 OK
2021/11/13 06:41:37 INFO  : only9: Copied (replaced existing)
2021/11/13 06:41:37 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncConcurrentTruncate (96.57s)
PASS
2021/11/13 06:42:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sumepov5hawiwem3zebowoq3': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 14m34.822403041s (try 1/5)