"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Starting (try 1/5)
2022/01/19 05:07:06 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2"
2022/01/19 05:07:06 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/01/19 05:07:06 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q"
2022/01/19 05:07:06 DEBUG : TestDrive: Loaded invalid token from config file - ignoring
2022/01/19 05:07:06 DEBUG : Saving config "token" in section "TestDrive" of the config file
2022/01/19 05:07:06 DEBUG : TestDrive: Saved new token in config file
2022/01/19 05:07:08 DEBUG : Creating backend with remote "/tmp/rclone1673842480"
=== 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-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:10 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2022/01/19 05:07:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
--- PASS: TestCopyWithDryRun (2.44s)
=== RUN   TestCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:14 DEBUG : sub dir/hello world: md5 = f4136adc1209467389f87e4218329aa3 OK
2022/01/19 05:07:14 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:07:16 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopy (5.98s)
=== RUN   TestCopyMissingDirectory
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:16 DEBUG : Creating backend with remote "/non-existing"
2022/01/19 05:07:17 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2022/01/19 05:07:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
--- PASS: TestCopyMissingDirectory (0.77s)
=== RUN   TestCopyNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:20 DEBUG : sub dir/hello world: md5 = 0291b0bb224cac28a0319dbbcbefe2a3 OK
2022/01/19 05:07:20 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:07:22 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyNoTraverse (5.74s)
=== RUN   TestCopyCheckFirst
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:23 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Running all checks before starting transfers
2022/01/19 05:07:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:23 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Checks finished, now starting transfers
2022/01/19 05:07:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:26 DEBUG : sub dir/hello world: md5 = 8727ab60fe3113b4151772be5893d831 OK
2022/01/19 05:07:26 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:07:28 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyCheckFirst (5.59s)
=== RUN   TestSyncNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:29 ERROR : Ignoring --no-traverse with sync
2022/01/19 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:32 DEBUG : sub dir/hello world: md5 = ee0360d89ce7dbdbd2e2a4859f02b1fc OK
2022/01/19 05:07:32 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:07:32 DEBUG : Waiting for deletions to finish
2022/01/19 05:07:33 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncNoTraverse (5.69s)
=== RUN   TestCopyWithDepth
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:36 DEBUG : hello world2: md5 = 827095d9b833cf13a7f2e2e5f371a66c OK
2022/01/19 05:07:36 INFO  : hello world2: Copied (new)
--- PASS: TestCopyWithDepth (3.24s)
=== RUN   TestCopyWithFilesFrom
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:38 DEBUG : hello world2: Excluded
2022/01/19 05:07:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:39 DEBUG : potato2: md5 = f7b2a37d06699fe779ec31e1530ff0f5 OK
2022/01/19 05:07:39 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFrom (3.39s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:43 DEBUG : potato2: md5 = b0e7fe8a7859e67b6f682a3a539f28df OK
2022/01/19 05:07:43 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFromAndNoTraverse (3.15s)
=== RUN   TestCopyEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:44 DEBUG : sub dir2: Making directory
2022/01/19 05:07:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:47 DEBUG : sub dir/hello world: md5 = b0dc77f197e068cd4c6df04cf375e770 OK
2022/01/19 05:07:47 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:07:47 DEBUG : sub dir2: Making directory
2022/01/19 05:07:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': copied 1 directories
2022/01/19 05:07:51 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyEmptyDirectories (7.65s)
=== RUN   TestMoveEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:52 DEBUG : sub dir2: Making directory
2022/01/19 05:07:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:07:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:07:55 DEBUG : sub dir/hello world: md5 = 673fd4b738cab29fb2b79b25f359e38b OK
2022/01/19 05:07:55 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:07:55 INFO  : sub dir/hello world: Deleted
2022/01/19 05:07:55 DEBUG : sub dir: Making directory
2022/01/19 05:07:55 DEBUG : sub dir2: Making directory
2022/01/19 05:07:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': copied 2 directories
2022/01/19 05:07:58 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestMoveEmptyDirectories (7.60s)
=== RUN   TestSyncEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:07:59 DEBUG : sub dir2: Making directory
2022/01/19 05:08:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:02 DEBUG : sub dir/hello world: md5 = 086efb884502662bf64efb5ade6d58d5 OK
2022/01/19 05:08:02 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:08:02 DEBUG : sub dir2: Making directory
2022/01/19 05:08:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': copied 1 directories
2022/01/19 05:08:03 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:06 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncEmptyDirectories (7.52s)
=== RUN   TestServerSideCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:09 DEBUG : sub dir/hello world: md5 = 771933b159d150824452b6c314188504 OK
2022/01/19 05:08:10 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nimerow3zicided5mehazus1"
2022/01/19 05:08:10 DEBUG : Creating backend with remote "TestDrive:crypt/ok2lloe5jmue2ad89kl9hgp9tvik3h1aqdh818rf1alv5u5qltv2vkk6unu3lf5r4mna97cd2tqhm"
    sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2' -> Encrypted drive 'TestCryptDrive:rclone-test-nimerow3zicided5mehazus1'
2022/01/19 05:08:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nimerow3zicided5mehazus1': Waiting for checks to finish
2022/01/19 05:08:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nimerow3zicided5mehazus1': Waiting for transfers to finish
2022/01/19 05:08:15 INFO  : sub dir/hello world: Copied (server-side copy)
2022/01/19 05:08:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nimerow3zicided5mehazus1': Purge remote
2022/01/19 05:08:17 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestServerSideCopy (11.55s)
=== RUN   TestCopyAfterDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:21 DEBUG : sub dir/hello world: md5 = d427acc02ed9b0c11da2198c5bd1409d OK
2022/01/19 05:08:21 ERROR : : error listing: directory not found
2022/01/19 05:08:21 DEBUG : Local file system at /tmp/rclone1673842480: Making directory
2022/01/19 05:08:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:24 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyAfterDelete (6.39s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:27 DEBUG : sub dir/hello world: md5 = db46fbf60f44c0709dd15abe6977c8cf OK
2022/01/19 05:08:29 DEBUG : Local file system at /tmp/rclone1673842480: Waiting for checks to finish
2022/01/19 05:08:29 DEBUG : Local file system at /tmp/rclone1673842480: Waiting for transfers to finish
2022/01/19 05:08:29 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:08:31 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyRedownload (7.07s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:34 DEBUG : check sum: md5 = 099be938a8b593df74fca796140de545 OK
2022/01/19 05:08:34 INFO  : check sum: Copied (new)
2022/01/19 05:08:34 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:34 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2022/01/19 05:08:34 DEBUG : check sum: Size of src and dst objects identical
2022/01/19 05:08:34 DEBUG : check sum: Unchanged skipping
2022/01/19 05:08:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:34 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:34 INFO  : There was nothing to transfer
--- PASS: TestSyncBasedOnCheckSum (3.92s)
=== RUN   TestSyncSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:37 DEBUG : sizeonly: md5 = 6eacf7c89a83b42ef8536e0a182a95a5 OK
2022/01/19 05:08:37 INFO  : sizeonly: Copied (new)
2022/01/19 05:08:37 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:38 DEBUG : sizeonly: Sizes identical
2022/01/19 05:08:38 DEBUG : sizeonly: Unchanged skipping
2022/01/19 05:08:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:38 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:38 INFO  : There was nothing to transfer
--- PASS: TestSyncSizeOnly (3.81s)
=== RUN   TestSyncIgnoreSize
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:41 DEBUG : ignore-size: md5 = 25ec0d43a2313d839fa9176c378b55aa OK
2022/01/19 05:08:41 INFO  : ignore-size: Copied (new)
2022/01/19 05:08:41 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:42 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:08:42 DEBUG : ignore-size: Unchanged skipping
2022/01/19 05:08:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:42 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:42 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreSize (3.95s)
=== RUN   TestSyncIgnoreTimes
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:45 DEBUG : existing: md5 = 3d1a9e9f20a21fef5fc2bb56049bbc79 OK
2022/01/19 05:08:46 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:08:46 DEBUG : existing: Unchanged skipping
2022/01/19 05:08:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:46 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:46 INFO  : There was nothing to transfer
2022/01/19 05:08:46 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2022/01/19 05:08:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:47 DEBUG : existing: md5 = c5d6d6699bfe1960af39b5a4035cb4ed OK
2022/01/19 05:08:47 INFO  : existing: Copied (replaced existing)
2022/01/19 05:08:47 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncIgnoreTimes (5.11s)
=== RUN   TestSyncIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:50 DEBUG : existing: md5 = ff7d596ff4f97b8fc2710790b696ea19 OK
2022/01/19 05:08:50 INFO  : existing: Copied (new)
2022/01/19 05:08:50 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:51 DEBUG : existing: Destination exists, skipping
2022/01/19 05:08:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:08:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:08:51 DEBUG : Waiting for deletions to finish
2022/01/19 05:08:51 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreExisting (3.93s)
=== RUN   TestSyncIgnoreErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:08:55 DEBUG : b/potato: md5 = c4a3665980cf91cdef4b3a11a66e5003 OK
2022/01/19 05:08:58 DEBUG : c/non empty space: md5 = 1eff82aa2177c442b2aa30a4b32d5db5 OK
2022/01/19 05:08:58 DEBUG : d: Making directory
2022/01/19 05:09:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:00 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:09:00 DEBUG : c/non empty space: Unchanged skipping
2022/01/19 05:09:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:02 DEBUG : a/potato2: md5 = 905728435d71e41a7c1c6544060ec9ac OK
2022/01/19 05:09:02 INFO  : a/potato2: Copied (new)
2022/01/19 05:09:02 DEBUG : Waiting for deletions to finish
2022/01/19 05:09:03 INFO  : b/potato: Deleted
2022/01/19 05:09:03 INFO  : d: Removing directory
2022/01/19 05:09:04 INFO  : b: Removing directory
2022/01/19 05:09:04 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/01/19 05:09:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': deleted 2 directories
2022/01/19 05:09:07 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/01/19 05:09:08 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncIgnoreErrors (16.04s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:10 DEBUG : empty space: md5 = 2e38e6494a893b9b0c1217494f45a430 OK
2022/01/19 05:09:11 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2022/01/19 05:09:11 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2022/01/19 05:09:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:11 DEBUG : Waiting for deletions to finish
2022/01/19 05:09:12 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2022/01/19 05:09:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:13 DEBUG : empty space: md5 = dfdc3d3e0847108d1dc18b583c53d193 OK
2022/01/19 05:09:13 INFO  : empty space: Copied (replaced existing)
2022/01/19 05:09:13 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingModtimeOnly (5.46s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
    sync_test.go:577: Can't check this if no hashes supported
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.52s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:16 DEBUG : foo: md5 = ff56f83cd8c1f801d94054a3817ef878 OK
2022/01/19 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:17 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2022/01/19 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:18 DEBUG : foo: md5 = 9a8339040f5263ef297eef56adc1555a OK
2022/01/19 05:09:18 INFO  : foo: Copied (replaced existing)
2022/01/19 05:09:18 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncDoesntUpdateModtime (4.47s)
=== RUN   TestSyncAfterAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:19 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:09:19 DEBUG : pacer: Rate limited, increasing sleep to 1.93372512s
    run.go:283: Retry Put of "empty space" to Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:09:22 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:09:24 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:09:24 DEBUG : pacer: Rate limited, increasing sleep to 1.528485531s
    run.go:283: Retry Put of "empty space" to Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': 2/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:09:26 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:09:28 DEBUG : empty space: md5 = da8710505cd2295cea7c77ae0fe4ba15 OK
2022/01/19 05:09:29 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:09:29 DEBUG : empty space: Unchanged skipping
2022/01/19 05:09:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:30 DEBUG : potato: md5 = 84fc55138cef7fbebc246a1f6a830482 OK
2022/01/19 05:09:30 INFO  : potato: Copied (new)
2022/01/19 05:09:30 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterAddingAFile (13.27s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:34 DEBUG : potato: md5 = fb8de32baa597f6f43597e6abc59771f OK
2022/01/19 05:09:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:34 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2022/01/19 05:09:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:35 DEBUG : potato: md5 = 282c64f3e2c262f4215be27d0297f67f OK
2022/01/19 05:09:35 INFO  : potato: Copied (replaced existing)
2022/01/19 05:09:35 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingFilesSizeOnly (4.46s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:38 DEBUG : potato: md5 = 5f269ff088cd9e1dd19e2fcf254eb941 OK
2022/01/19 05:09:39 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC
2022/01/19 05:09:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:40 DEBUG : potato: md5 = 5c46aa4ca464ce4a3fb4ca4e99f7e407 OK
2022/01/19 05:09:40 INFO  : potato: Copied (replaced existing)
2022/01/19 05:09:40 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingContentsOnly (4.52s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:43 DEBUG : potato: md5 = b80c2ff2d691872f37e11e9eac286503 OK
2022/01/19 05:09:44 DEBUG : empty space: md5 = 42d5a8745f05d89127751a3b576a14f9 OK
2022/01/19 05:09:45 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2022/01/19 05:09:45 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:09:45 DEBUG : empty space: Unchanged skipping
2022/01/19 05:09:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:45 DEBUG : Waiting for deletions to finish
2022/01/19 05:09:45 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.17s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:48 DEBUG : potato: md5 = 9a0d6c1bbe51b413b00102c0a9845147 OK
2022/01/19 05:09:49 DEBUG : empty space: md5 = 4b7c5dc68070536e5473123330f5fdf6 OK
2022/01/19 05:09:50 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:09:50 DEBUG : empty space: Unchanged skipping
2022/01/19 05:09:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:09:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:09:51 DEBUG : potato2: md5 = 42a2949d258b6140c9925dd3b34ff6f6 OK
2022/01/19 05:09:51 INFO  : potato2: Copied (new)
2022/01/19 05:09:51 DEBUG : Waiting for deletions to finish
2022/01/19 05:09:52 INFO  : potato: Deleted
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.37s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:09:55 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:09:55 DEBUG : pacer: Rate limited, increasing sleep to 1.721573002s
2022/01/19 05:09:55 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:09:57 DEBUG : b/potato: md5 = 19f853305676f2b55291b0ead5de65b4 OK
2022/01/19 05:10:00 DEBUG : c/non empty space: md5 = d9e4cf2f7288389df90474efab4e81cf OK
2022/01/19 05:10:00 DEBUG : d: Making directory
2022/01/19 05:10:01 DEBUG : d/e: Making directory
2022/01/19 05:10: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)
2022/01/19 05:10:03 DEBUG : pacer: Rate limited, increasing sleep to 1.372959258s
2022/01/19 05:10:03 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:10:03 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:10:03 DEBUG : c/non empty space: Unchanged skipping
2022/01/19 05:10:03 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:10:03 DEBUG : pacer: Rate limited, increasing sleep to 1.736462424s
2022/01/19 05:10:05 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:10:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:09 DEBUG : a/potato2: md5 = ba5aa29bbc2c21db40869efc6cc0f9dd OK
2022/01/19 05:10:09 INFO  : a/potato2: Copied (new)
2022/01/19 05:10:09 DEBUG : Waiting for deletions to finish
2022/01/19 05:10:09 INFO  : b/potato: Deleted
2022/01/19 05:10:09 INFO  : d/e: Removing directory
2022/01/19 05:10:10 INFO  : d: Removing directory
2022/01/19 05:10:10 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8"
2022/01/19 05:10:11 INFO  : b: Removing directory
2022/01/19 05:10:11 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/01/19 05:10:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': deleted 3 directories
2022/01/19 05:10:14 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/01/19 05:10:15 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (22.43s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:10:19 DEBUG : b/potato: md5 = 6f501f94db3bec4ebeb70505e1376e8e OK
2022/01/19 05:10:21 DEBUG : c/non empty space: md5 = 7b9b18871e8b7557c285e4a276648307 OK
2022/01/19 05:10:21 DEBUG : d: Making directory
2022/01/19 05:10:23 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:10:23 DEBUG : c/non empty space: Unchanged skipping
2022/01/19 05:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:25 DEBUG : a/potato2: md5 = 97ff24be92ffeffe27650c002d31338a OK
2022/01/19 05:10:25 INFO  : a/potato2: Copied (new)
2022/01/19 05:10:25 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': not deleting files as there were IO errors
2022/01/19 05:10:25 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': not deleting directories as there were IO errors
2022/01/19 05:10:26 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:10:26 DEBUG : pacer: Rate limited, increasing sleep to 1.446502989s
2022/01/19 05:10:26 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:10:27 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:10:27 DEBUG : pacer: Rate limited, increasing sleep to 1.083185706s
2022/01/19 05:10:28 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:10:32 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/01/19 05:10:32 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/01/19 05:10:33 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (17.83s)
=== RUN   TestSyncDeleteAfter
--- PASS: TestSyncDeleteAfter (0.00s)
=== RUN   TestSyncDeleteDuring
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:10:36 DEBUG : potato: md5 = 18dcbb78b4125fe7fd8dbcda0195c709 OK
2022/01/19 05:10:37 DEBUG : empty space: md5 = 31834a5c95c90a2f37d160d7386a2a5f OK
2022/01/19 05:10:37 DEBUG : Waiting for deletions to finish
2022/01/19 05:10:38 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:10:38 DEBUG : empty space: Unchanged skipping
2022/01/19 05:10:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:38 INFO  : potato: Deleted
2022/01/19 05:10:39 DEBUG : potato2: md5 = a36caca3c38c90e44f8c4fa88c4bef3c OK
2022/01/19 05:10:39 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteDuring (6.97s)
=== RUN   TestSyncDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:10:43 DEBUG : potato: md5 = e20840daeed260d0ccbe7c876ce73df7 OK
2022/01/19 05:10:44 DEBUG : empty space: md5 = 5e43084c4464e2eb7a81d630ed255d5f OK
2022/01/19 05:10:44 DEBUG : Waiting for deletions to finish
2022/01/19 05:10:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:45 INFO  : potato: Deleted
2022/01/19 05:10:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:45 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:10:45 DEBUG : empty space: Unchanged skipping
2022/01/19 05:10:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:47 DEBUG : potato2: md5 = 6ccd26f474fa2655e78ae388ee1b31a7 OK
2022/01/19 05:10:47 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteBefore (8.13s)
=== RUN   TestCopyDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:10:51 DEBUG : potato: md5 = 37fcd8ec87165e4ffa093e24dbb3dd05 OK
2022/01/19 05:10:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:53 DEBUG : potato2: md5 = f7dbdff60d51e89d515ccde5c4145431 OK
2022/01/19 05:10:53 INFO  : potato2: Copied (new)
--- PASS: TestCopyDeleteBefore (5.71s)
=== RUN   TestSyncWithExclude
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:10:56 DEBUG : potato2: md5 = e75aa1697a7bae3cc7ea414439d483c7 OK
2022/01/19 05:10:58 DEBUG : empty space: md5 = 83641017b5577623a65af69de27eb8cd OK
2022/01/19 05:10:58 DEBUG : enormous: Excluded
2022/01/19 05:10:58 DEBUG : potato2: Excluded
2022/01/19 05:10:58 DEBUG : potato2: Excluded
2022/01/19 05:10:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:10:58 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:10:58 DEBUG : empty space: Unchanged skipping
2022/01/19 05:10:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:10:58 DEBUG : Waiting for deletions to finish
2022/01/19 05:10:58 INFO  : There was nothing to transfer
2022/01/19 05:10:59 DEBUG : enormous: Excluded
2022/01/19 05:10:59 DEBUG : potato2: Excluded
2022/01/19 05:10:59 DEBUG : potato2: Excluded
2022/01/19 05:10:59 DEBUG : Local file system at /tmp/rclone1673842480: Waiting for checks to finish
2022/01/19 05:10:59 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2022/01/19 05:10:59 DEBUG : empty space: Unchanged skipping
2022/01/19 05:10:59 DEBUG : Local file system at /tmp/rclone1673842480: Waiting for transfers to finish
2022/01/19 05:10:59 DEBUG : Waiting for deletions to finish
2022/01/19 05:10:59 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExclude (5.88s)
=== RUN   TestSyncWithExcludeAndDeleteExcluded
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:11:02 DEBUG : potato2: md5 = eda52934133fdae23c04850d630d2831 OK
2022/01/19 05:11:04 DEBUG : empty space: md5 = e338ad78dc0feb74870e44e8b9c957c3 OK
2022/01/19 05:11:05 DEBUG : enormous: md5 = 1d1de2e1433c48ebf6ec367184fff77f OK
2022/01/19 05:11:06 DEBUG : enormous: Excluded
2022/01/19 05:11:06 DEBUG : potato2: Excluded
2022/01/19 05:11:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:06 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:11:06 DEBUG : empty space: Unchanged skipping
2022/01/19 05:11:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:06 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:07 INFO  : potato2: Deleted
2022/01/19 05:11:07 INFO  : enormous: Deleted
2022/01/19 05:11:07 INFO  : There was nothing to transfer
2022/01/19 05:11:07 DEBUG : Local file system at /tmp/rclone1673842480: Waiting for checks to finish
2022/01/19 05:11:07 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2022/01/19 05:11:07 DEBUG : empty space: Unchanged skipping
2022/01/19 05:11:07 DEBUG : Local file system at /tmp/rclone1673842480: Waiting for transfers to finish
2022/01/19 05:11:07 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:07 INFO  : enormous: Deleted
2022/01/19 05:11:07 INFO  : potato2: Deleted
2022/01/19 05:11:07 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExcludeAndDeleteExcluded (7.70s)
=== RUN   TestSyncWithUpdateOlder
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:11:10 DEBUG : one: md5 = a53b27fb954b6fb1ae4d8c62f4cdd5ab OK
2022/01/19 05:11:12 DEBUG : two: md5 = 79888d2c5e35f7db627bbe3ee8d0a71a OK
2022/01/19 05:11:13 DEBUG : three: md5 = 87486bfd89b52388969ec763118f5cde OK
2022/01/19 05:11:15 DEBUG : four: md5 = fac072d89b2d37e76acec36af7e89fed OK
2022/01/19 05:11:15 DEBUG : four: Sizes differ (src 4 vs dst 8)
2022/01/19 05:11:15 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring
2022/01/19 05:11:15 DEBUG : one: Destination is newer than source, skipping
2022/01/19 05:11:15 DEBUG : three: Sizes identical
2022/01/19 05:11:15 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping
2022/01/19 05:11:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:16 DEBUG : four: md5 = 94871fde19c47d753d7971184e3b0947 OK
2022/01/19 05:11:16 INFO  : four: Copied (replaced existing)
2022/01/19 05:11:16 DEBUG : two: md5 = 09ea4e1695cd0e4a66236fe9b18e8c19 OK
2022/01/19 05:11:16 INFO  : two: Copied (replaced existing)
2022/01/19 05:11:17 DEBUG : five: md5 = 6b3a569da87896c99cdf6f2db5e33932 OK
2022/01/19 05:11:17 INFO  : five: Copied (new)
2022/01/19 05:11:17 DEBUG : Waiting for deletions to finish
    sync_test.go:992: Skip test with --checksum as no hashes supported
--- PASS: TestSyncWithUpdateOlder (12.12s)
=== 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-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
    sync_test.go:1058: Can track renames: false
2022/01/19 05:11:21 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Ignoring --track-renames as the source and destination do not have a common hash
2022/01/19 05:11:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:22 DEBUG : yam: md5 = 1c3924424b2524157e18a8ebb7b803b4 OK
2022/01/19 05:11:22 INFO  : yam: Copied (new)
2022/01/19 05:11:23 DEBUG : potato: md5 = d61ad7f8ba75b4f5d754764386afe635 OK
2022/01/19 05:11:23 INFO  : potato: Copied (new)
2022/01/19 05:11:23 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:23 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Ignoring --track-renames as the source and destination do not have a common hash
2022/01/19 05:11:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:23 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:11:23 DEBUG : potato: Unchanged skipping
2022/01/19 05:11:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:25 DEBUG : yaml: md5 = bf74f869522caca936dd91325d0f6c7e OK
2022/01/19 05:11:25 INFO  : yaml: Copied (new)
2022/01/19 05:11:25 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:26 INFO  : yam: Deleted
--- PASS: TestSyncWithTrackRenames (7.10s)
=== RUN   TestParseRenamesStrategyModtime
--- PASS: TestParseRenamesStrategyModtime (0.00s)
=== RUN   TestRenamesStrategyModtime
--- PASS: TestRenamesStrategyModtime (0.00s)
=== RUN   TestSyncWithTrackRenamesStrategyModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
    sync_test.go:1127: Can track renames: true
2022/01/19 05:11:28 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Making map for --track-renames
2022/01/19 05:11:28 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Finished making map for --track-renames
2022/01/19 05:11:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for renames to finish
2022/01/19 05:11:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:29 DEBUG : potato: md5 = f3c9032f96c3e255d4d04d2130f02b40 OK
2022/01/19 05:11:29 INFO  : potato: Copied (new)
2022/01/19 05:11:30 DEBUG : yam: md5 = b29f57c754e9227219b2993d777ed96a OK
2022/01/19 05:11:30 INFO  : yam: Copied (new)
2022/01/19 05:11:30 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:30 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:11:30 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Making map for --track-renames
2022/01/19 05:11:30 DEBUG : potato: Unchanged skipping
2022/01/19 05:11:30 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Finished making map for --track-renames
2022/01/19 05:11:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for renames to finish
2022/01/19 05:11:31 INFO  : yam: Moved (server-side) to: yaml
2022/01/19 05:11:31 INFO  : yaml: Renamed from "yam"
2022/01/19 05:11:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:31 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:31 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyModtime (5.88s)
=== RUN   TestSyncWithTrackRenamesStrategyLeaf
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
    sync_test.go:1163: Can track renames: true
2022/01/19 05:11:34 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Making map for --track-renames
2022/01/19 05:11:34 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Finished making map for --track-renames
2022/01/19 05:11:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for renames to finish
2022/01/19 05:11:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:37 DEBUG : sub/yam: md5 = b577a9b9e6575d03640f49ddbb096180 OK
2022/01/19 05:11:37 INFO  : sub/yam: Copied (new)
2022/01/19 05:11:37 DEBUG : potato: md5 = ce42d10407d0af65707d784ace37da02 OK
2022/01/19 05:11:37 INFO  : potato: Copied (new)
2022/01/19 05:11:37 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:37 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:11:37 DEBUG : potato: Unchanged skipping
2022/01/19 05:11:38 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Making map for --track-renames
2022/01/19 05:11:38 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Finished making map for --track-renames
2022/01/19 05:11:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for renames to finish
2022/01/19 05:11:39 INFO  : sub/yam: Moved (server-side) to: yam
2022/01/19 05:11:39 INFO  : yam: Renamed from "sub/yam"
2022/01/19 05:11:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:39 DEBUG : Waiting for deletions to finish
2022/01/19 05:11:39 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyLeaf (8.93s)
=== RUN   TestMoveWithDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:11:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:45 DEBUG : sub dir/hello world: md5 = 890d1863460850b287853f84da696e86 OK
2022/01/19 05:11:45 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:11:45 INFO  : sub dir/hello world: Deleted
2022/01/19 05:11:48 DEBUG : nested/sub dir/file: md5 = 7404fd6cdecaf204e450fb6c74a8108d OK
2022/01/19 05:11:48 INFO  : nested/sub dir/file: Copied (new)
2022/01/19 05:11:48 INFO  : nested/sub dir/file: Deleted
2022/01/19 05:11:48 INFO  : sub dir: Removing directory
2022/01/19 05:11:48 INFO  : nested/sub dir: Removing directory
2022/01/19 05:11:48 INFO  : nested: Removing directory
2022/01/19 05:11:48 DEBUG : Local file system at /tmp/rclone1673842480: deleted 3 directories
2022/01/19 05:11:51 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2022/01/19 05:11:52 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2022/01/19 05:11:52 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithDeleteEmptySrcDirs (10.76s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:11:56 DEBUG : sub dir/hello world: md5 = e75febcf49851221056709772bfd2c7f OK
2022/01/19 05:11:56 INFO  : sub dir/hello world: Copied (new)
2022/01/19 05:11:56 INFO  : sub dir/hello world: Deleted
2022/01/19 05:11:58 DEBUG : nested/sub dir/file: md5 = 218128995776c11846ac36f582f6fc1f OK
2022/01/19 05:11:58 INFO  : nested/sub dir/file: Copied (new)
2022/01/19 05:11:58 INFO  : nested/sub dir/file: Deleted
2022/01/19 05:11:59 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:11:59 DEBUG : pacer: Rate limited, increasing sleep to 1.692933687s
2022/01/19 05:11:59 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:11:59 DEBUG : pacer: Rate limited, increasing sleep to 2.425464048s
2022/01/19 05:12:01 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:12: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)
2022/01/19 05:12:03 DEBUG : pacer: Rate limited, increasing sleep to 1.169062001s
2022/01/19 05:12:04 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:12:06 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2022/01/19 05:12:07 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2022/01/19 05:12:08 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (15.23s)
=== RUN   TestMoveWithIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:12:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:12:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:12:10 DEBUG : existing: md5 = 5491e4570958264aa043ac0f7d0bd52d OK
2022/01/19 05:12:10 INFO  : existing: Copied (new)
2022/01/19 05:12:10 INFO  : existing: Deleted
2022/01/19 05:12:11 DEBUG : existing-b: md5 = adbb61f5e68bba12ccb18661b78b917d OK
2022/01/19 05:12:11 INFO  : existing-b: Copied (new)
2022/01/19 05:12:11 INFO  : existing-b: Deleted
2022/01/19 05:12:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:12:11 DEBUG : existing: Destination exists, skipping
2022/01/19 05:12:11 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set
2022/01/19 05:12:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:12:11 INFO  : There was nothing to transfer
--- PASS: TestMoveWithIgnoreExisting (4.75s)
=== RUN   TestServerSideMove
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:12:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5"
2022/01/19 05:12:13 DEBUG : Creating backend with remote "TestDrive:crypt/u78b76gh7gg7aqscc3u894q8p1nbfbebdkgh0nh43rlv2a8e5e4kprpk5kjeqm6pulp5i65tpsgvo"
2022/01/19 05:12:16 DEBUG : potato2: md5 = 1078a00a89ba228df5654cbe1c3900af OK
2022/01/19 05:12:16 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:12:16 DEBUG : pacer: Rate limited, increasing sleep to 1.389879491s
2022/01/19 05:12:16 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:12:16 DEBUG : pacer: Rate limited, increasing sleep to 2.469864567s
2022/01/19 05:12:18 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:12:21 DEBUG : empty space: md5 = a4cc64547dee0b5e6bdad46ab725b6b0 OK
2022/01/19 05:12:22 DEBUG : potato3: md5 = 8b711145e9726194fae22730cea88bd3 OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2' -> Encrypted drive 'TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5'
2022/01/19 05:12:25 DEBUG : empty space: md5 = c721ce1a04a8845ba60cba5c543e5d06 OK
2022/01/19 05:12:26 DEBUG : potato3: md5 = 99f6345e95c1fa53e959eff69ffd2e5a OK
2022/01/19 05:12:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5': Using server-side directory move
2022/01/19 05:12:27 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2022/01/19 05:12:27 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2022/01/19 05:12:27 DEBUG : empty space: Unchanged skipping
2022/01/19 05:12:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5': Waiting for checks to finish
2022/01/19 05:12:27 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/01/19 05:12:28 INFO  : empty space: Deleted
2022/01/19 05:12:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5': Waiting for transfers to finish
2022/01/19 05:12:28 INFO  : potato3: Deleted
2022/01/19 05:12:28 INFO  : potato2: Moved (server-side)
2022/01/19 05:12:28 INFO  : potato3: Moved (server-side)
2022/01/19 05:12:28 INFO  : There was nothing to transfer
2022/01/19 05:12:29 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-lufegek9reqakiw5mebinek2"
2022/01/19 05:12:29 DEBUG : Creating backend with remote "TestDrive:crypt/v8998r0ap2m0rvphgiaepb1ctg1u72ju8vcqjrv0bgende0v625sbvdit2ldqov6ic802nd8o39uu"
2022/01/19 05:12:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lufegek9reqakiw5mebinek2': Using server-side directory move
2022/01/19 05:12:31 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-lufegek9reqakiw5mebinek2': Server side directory move succeeded
2022/01/19 05:12:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lufegek9reqakiw5mebinek2': Purge remote
2022/01/19 05:12:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rapesol7hexilar0dupedem5': Purge remote
2022/01/19 05:12:33 purge failed: directory not found
--- PASS: TestServerSideMove (20.19s)
=== RUN   TestServerSideMoveWithFilter
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:12:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nukobel1zikojib5nafopen2"
2022/01/19 05:12:33 DEBUG : Creating backend with remote "TestDrive:crypt/acmp4tfqi78l69sar4puokkkp6879uoog4j68ghd55c4f9ck7ub6fr4kt4p8e9fbbkhr9hckgjeme"
2022/01/19 05:12:36 DEBUG : potato2: md5 = 8205548f9dd9dd5f6b516e1ffee4e33f OK
2022/01/19 05:12:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:12:36 DEBUG : pacer: Rate limited, increasing sleep to 1.786365998s
2022/01/19 05:12:36 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:12:36 DEBUG : pacer: Rate limited, increasing sleep to 2.281297285s
2022/01/19 05:12:38 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:12:41 DEBUG : empty space: md5 = bae6095bea0a17e95a84b948c2d8e87e OK
2022/01/19 05:12:43 DEBUG : potato3: md5 = ecf399131d8d715e5d0d08fd2cfc6639 OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2' -> Encrypted drive 'TestCryptDrive:rclone-test-nukobel1zikojib5nafopen2'
2022/01/19 05:12:46 DEBUG : empty space: md5 = c11c5a11fbda83ecc38ce7e155ccd51c OK
2022/01/19 05:12:47 DEBUG : potato3: md5 = 7c407c0fc799541552e0f0174fda2edb OK
2022/01/19 05:12:48 DEBUG : empty space: Excluded
2022/01/19 05:12:48 DEBUG : empty space: Excluded
2022/01/19 05:12:48 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/01/19 05:12:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nukobel1zikojib5nafopen2': Waiting for checks to finish
2022/01/19 05:12:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nukobel1zikojib5nafopen2': Waiting for transfers to finish
2022/01/19 05:12:49 INFO  : potato3: Deleted
2022/01/19 05:12:49 INFO  : potato2: Moved (server-side)
2022/01/19 05:12:50 INFO  : potato3: Moved (server-side)
2022/01/19 05:12:50 INFO  : There was nothing to transfer
2022/01/19 05:12:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-mojugim7hikivoz8duluhoz7"
2022/01/19 05:12:50 DEBUG : Creating backend with remote "TestDrive:crypt/iraj8qhpjs5h0uqepfhk9o0tfth6pva17vm7r3k361ga6c8d1io02i6aisl3adh2thansah14jkqe"
2022/01/19 05:12:52 DEBUG : empty space: Excluded
2022/01/19 05:12:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mojugim7hikivoz8duluhoz7': Waiting for checks to finish
2022/01/19 05:12:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mojugim7hikivoz8duluhoz7': Waiting for transfers to finish
2022/01/19 05:12:53 INFO  : potato2: Moved (server-side)
2022/01/19 05:12:54 INFO  : potato3: Moved (server-side)
2022/01/19 05:12:54 INFO  : There was nothing to transfer
2022/01/19 05:12:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-mojugim7hikivoz8duluhoz7': Purge remote
2022/01/19 05:12:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nukobel1zikojib5nafopen2': Purge remote
--- PASS: TestServerSideMoveWithFilter (23.26s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:12:57 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1"
2022/01/19 05:12:57 DEBUG : Creating backend with remote "TestDrive:crypt/q9jnv126gkmgvc9p1hlop129hq3mlpntbi9822c02upnc3qd9he9438buo6daii3468jqsq9dk6ja"
2022/01/19 05:12:59 DEBUG : potato2: md5 = 7905e0fdab33169e6a8266680cfcb9cd OK
2022/01/19 05:13:01 DEBUG : empty space: md5 = 56b74a1a48eaa230a321a49c520bb528 OK
2022/01/19 05:13:02 DEBUG : potato3: md5 = ab08c356ededb9f21e97b7ab4bff46c8 OK
2022/01/19 05:13:02 DEBUG : tomatoDir: Making directory
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2' -> Encrypted drive 'TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1'
2022/01/19 05:13:06 DEBUG : empty space: md5 = 451e33dcb7b972ac207ffe0401b92c2b OK
2022/01/19 05:13:08 DEBUG : potato3: md5 = 408b2996fad0854271a9af730816f43b OK
2022/01/19 05:13:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1': Using server-side directory move
2022/01/19 05:13:08 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2022/01/19 05:13:09 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2022/01/19 05:13:09 DEBUG : empty space: Unchanged skipping
2022/01/19 05:13:09 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/01/19 05:13:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1': Waiting for checks to finish
2022/01/19 05:13:09 INFO  : empty space: Deleted
2022/01/19 05:13:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1': Waiting for transfers to finish
2022/01/19 05:13:09 INFO  : potato3: Deleted
2022/01/19 05:13:10 INFO  : potato2: Moved (server-side)
2022/01/19 05:13:10 INFO  : potato3: Moved (server-side)
2022/01/19 05:13:10 INFO  : tomatoDir: Removing directory
2022/01/19 05:13:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': deleted 1 directories
2022/01/19 05:13:11 INFO  : There was nothing to transfer
2022/01/19 05:13:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-faludad3cazitep5desarad2"
2022/01/19 05:13:12 DEBUG : Creating backend with remote "TestDrive:crypt/2n08eeo857rf1rghtq32qr8vvh66656nvkuhj53qcakgbtvelnte5o1pjqm26vojpb6p357im29fk"
2022/01/19 05:13:13 DEBUG : tomatoDir: Making directory
2022/01/19 05:13:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-faludad3cazitep5desarad2': Using server-side directory move
2022/01/19 05:13:15 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-faludad3cazitep5desarad2': Server side directory move succeeded
2022/01/19 05:13:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-faludad3cazitep5desarad2': Purge remote
2022/01/19 05:13:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xequtiy6jakamaj5hebores1': Purge remote
2022/01/19 05:13:17 purge failed: directory not found
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (21.21s)
=== RUN   TestServerSideMoveOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
    sync_test.go:1399: Skipping test as remote supports DirMove
--- SKIP: TestServerSideMoveOverlap (0.49s)
=== RUN   TestSyncOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:13:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/rclone-sync-test"
2022/01/19 05:13:18 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0"
--- PASS: TestSyncOverlap (2.44s)
=== RUN   TestSyncCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:13:21 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:13:21 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:13:23 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/CompareDest"
2022/01/19 05:13:23 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/gveqi14airsml4bgu7krj116o8"
2022/01/19 05:13:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:13:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:13:27 DEBUG : one: md5 = 66e480655893b96a741f55782d47c086 OK
2022/01/19 05:13:27 INFO  : one: Copied (new)
2022/01/19 05:13:27 DEBUG : Waiting for deletions to finish
2022/01/19 05:13:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:13:29 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/01/19 05:13:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:13:30 DEBUG : one: md5 = 456df24e0119502f4fd1929cede1677e OK
2022/01/19 05:13:30 INFO  : one: Copied (replaced existing)
2022/01/19 05:13:30 DEBUG : Waiting for deletions to finish
2022/01/19 05:13:32 DEBUG : dst/one: md5 = 3d24a3fe7a3a2c816c459f8396e6ec4b OK
2022/01/19 05:13:34 DEBUG : CompareDest/one: md5 = 34b138eb9a056ecc099ec8ab0ad91bb7 OK
2022/01/19 05:13:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:13:36 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:13:36 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/19 05:13:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:13:36 DEBUG : Waiting for deletions to finish
2022/01/19 05:13:36 INFO  : There was nothing to transfer
2022/01/19 05:13:38 DEBUG : CompareDest/two: md5 = f8284c68439e80be8769479ff2498ff1 OK
2022/01/19 05:13:39 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:13:39 DEBUG : two: Destination found in --compare-dest, skipping
2022/01/19 05:13:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:13:39 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:13:39 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/19 05:13:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:13:39 DEBUG : Waiting for deletions to finish
2022/01/19 05:13:39 INFO  : There was nothing to transfer
2022/01/19 05:13:41 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:13:41 DEBUG : two: Destination found in --compare-dest, skipping
2022/01/19 05:13:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:13:41 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:13:41 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/19 05:13:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:13:41 DEBUG : Waiting for deletions to finish
2022/01/19 05:13:41 INFO  : There was nothing to transfer
    sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test
2022/01/19 05:13:43 DEBUG : two: Sizes differ (src 5 vs dst 3)
2022/01/19 05:13:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:13:43 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:13:43 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/19 05:13:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:13:44 DEBUG : two: md5 = 6085a0ca5f699c9e6de9573b6939c661 OK
2022/01/19 05:13:44 INFO  : two: Copied (new)
2022/01/19 05:13:44 DEBUG : Waiting for deletions to finish
2022/01/19 05:13:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:13:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:13:49 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:13:49 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
--- PASS: TestSyncCompareDest (29.02s)
=== RUN   TestSyncMultipleCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:13:51 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:13:51 DEBUG : pacer: Rate limited, increasing sleep to 1.436297934s
2022/01/19 05:13:51 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:13:53 DEBUG : pre-dest1/1: md5 = 9ab1027f682d2687a0367372dda668d7 OK
2022/01/19 05:13:56 DEBUG : pre-dest2/2: md5 = 59013218c5f7b0c6cd6ccc4a01d42030 OK
2022/01/19 05:13:56 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dest"
2022/01/19 05:13:56 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/rg03c1jvnehrrc617i0lnqjddc"
2022/01/19 05:13:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/pre-dest1"
2022/01/19 05:13:58 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/bbnblvh6k061ssopqrp18kd7gc"
2022/01/19 05:13:59 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/pre-dest2"
2022/01/19 05:13:59 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/dgicm1h6b5ejvlltm8eeif0bnk"
2022/01/19 05:14:00 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:14:00 DEBUG : pacer: Rate limited, increasing sleep to 1.206971627s
2022/01/19 05:14:00 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:14:00 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:14:00 DEBUG : 1: Destination found in --compare-dest, skipping
2022/01/19 05:14:01 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:14:01 DEBUG : 2: Destination found in --compare-dest, skipping
2022/01/19 05:14:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dest': Waiting for checks to finish
2022/01/19 05:14:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dest': Waiting for transfers to finish
2022/01/19 05:14:04 DEBUG : 3: md5 = 7fbdcccda99a280d03b042a6927a816b OK
2022/01/19 05:14:04 INFO  : 3: Copied (new)
2022/01/19 05:14:04 DEBUG : Waiting for deletions to finish
2022/01/19 05:14: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)
2022/01/19 05:14:04 DEBUG : pacer: Rate limited, increasing sleep to 1.228011798s
2022/01/19 05:14: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)
2022/01/19 05:14:05 DEBUG : pacer: Rate limited, increasing sleep to 2.576497638s
2022/01/19 05:14:06 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:14:11 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc"
2022/01/19 05:14:12 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro"
2022/01/19 05:14:13 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg"
--- PASS: TestSyncMultipleCompareDest (24.00s)
=== RUN   TestSyncCopyDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:14:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:14:14 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:14:16 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:14:16 DEBUG : pacer: Rate limited, increasing sleep to 1.890655273s
2022/01/19 05:14:16 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:14:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/CopyDest"
2022/01/19 05:14:16 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/d09o6po3f7bm6ce32vdgs8h9ls"
2022/01/19 05:14:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:14:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:14:20 DEBUG : one: md5 = 8f7e7914cdbc63a0abcb223500626961 OK
2022/01/19 05:14:20 INFO  : one: Copied (new)
2022/01/19 05:14:20 DEBUG : Waiting for deletions to finish
2022/01/19 05:14:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:14:22 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/01/19 05:14:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:14:23 DEBUG : one: md5 = bcb4741b10ac361b82c2c2115897c7c4 OK
2022/01/19 05:14:23 INFO  : one: Copied (replaced existing)
2022/01/19 05:14:23 DEBUG : Waiting for deletions to finish
2022/01/19 05:14:25 DEBUG : dst/one: md5 = 76fac0f3efd2b46d2b7f46ea8f045c4d OK
2022/01/19 05:14:26 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:14:26 DEBUG : pacer: Rate limited, increasing sleep to 1.868458491s
2022/01/19 05:14:26 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:14:26 DEBUG : pacer: Rate limited, increasing sleep to 2.095532231s
2022/01/19 05:14:28 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:14:31 DEBUG : CopyDest/one: md5 = aa8271cab562de61fa19454a3d08e878 OK
2022/01/19 05:14:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/BackupDir"
2022/01/19 05:14:32 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/s6dbk3lfi7c9kfvo6j7bla9m0g"
2022/01/19 05:14:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:14:34 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:34 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/01/19 05:14:36 INFO  : one: Moved (server-side)
2022/01/19 05:14:37 INFO  : one: Copied (server-side copy)
2022/01/19 05:14:37 DEBUG : one: Destination found in --copy-dest, using server-side copy
2022/01/19 05:14:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:14:37 DEBUG : Waiting for deletions to finish
2022/01/19 05:14:40 DEBUG : CopyDest/two: md5 = 0a172dc3e3abee678fb4e86d47662ae4 OK
2022/01/19 05:14:41 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:42 INFO  : two: Copied (server-side copy)
2022/01/19 05:14:42 DEBUG : two: Destination found in --copy-dest, using server-side copy
2022/01/19 05:14:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:14:42 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:42 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:42 DEBUG : one: Unchanged skipping
2022/01/19 05:14:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:14:42 DEBUG : Waiting for deletions to finish
2022/01/19 05:14:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:14:44 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:44 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:44 DEBUG : one: Unchanged skipping
2022/01/19 05:14:44 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:44 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:44 DEBUG : two: Unchanged skipping
2022/01/19 05:14:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:14:44 DEBUG : Waiting for deletions to finish
2022/01/19 05:14:44 INFO  : There was nothing to transfer
2022/01/19 05:14:46 DEBUG : CopyDest/three: md5 = d35ef7b915d2c61b81feeb4a15676128 OK
2022/01/19 05:14:47 DEBUG : three: Sizes differ (src 7 vs dst 5)
2022/01/19 05:14:47 DEBUG : three: Destination not found in --copy-dest
2022/01/19 05:14:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:14:47 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:47 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:47 DEBUG : two: Unchanged skipping
2022/01/19 05:14:47 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:47 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/19 05:14:47 DEBUG : one: Unchanged skipping
2022/01/19 05:14:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:14:48 DEBUG : three: md5 = 1cc864f0db8140d6d5cb5f1bf49c5dde OK
2022/01/19 05:14:48 INFO  : three: Copied (new)
2022/01/19 05:14:48 DEBUG : Waiting for deletions to finish
2022/01/19 05:14:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2022/01/19 05:14:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:14:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:14:55 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2022/01/19 05:14:55 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:14:55 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:14:56 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:14:56 DEBUG : pacer: Rate limited, increasing sleep to 1.41835528s
2022/01/19 05:14:56 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:14:56 DEBUG : pacer: Rate limited, increasing sleep to 2.581439028s
2022/01/19 05:14:57 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:14:57 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
--- PASS: TestSyncCopyDest (46.67s)
=== RUN   TestSyncBackupDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:15:03 DEBUG : dst/one: md5 = 292473198dd2a45e9a3fe33296bf41d1 OK
2022/01/19 05:15:05 DEBUG : dst/two: md5 = 03db2c5bd3b0fb3d06625408ac7471f4 OK
2022/01/19 05:15:06 DEBUG : dst/three.txt: md5 = 191efe11aa7f81552278b448324d4fe5 OK
2022/01/19 05:15:07 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:15:07 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:15:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/backup"
2022/01/19 05:15:08 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/1nrff024r7pq65ecp72fc28jb0"
2022/01/19 05:15:10 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/19 05:15:10 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:15:10 DEBUG : two: Unchanged skipping
2022/01/19 05:15:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:15:12 INFO  : one: Moved (server-side)
2022/01/19 05:15:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:15:14 DEBUG : one: md5 = 6a73da132fc3d897bc07c855fc2c9b0f OK
2022/01/19 05:15:14 INFO  : one: Copied (new)
2022/01/19 05:15:14 DEBUG : Waiting for deletions to finish
2022/01/19 05:15:15 INFO  : three.txt: Moved (server-side)
2022/01/19 05:15:15 INFO  : three.txt: Moved into backup dir
2022/01/19 05:15:17 DEBUG : dst/three.txt: md5 = f293e7062ad78da0c061d131539ee3a9 OK
2022/01/19 05:15:18 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/19 05:15:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:15:18 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:15:18 DEBUG : two: Unchanged skipping
2022/01/19 05:15:19 INFO  : one: Deleted
2022/01/19 05:15:20 INFO  : one: Moved (server-side)
2022/01/19 05:15:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:15:21 DEBUG : one: md5 = ed36bebb3e5ab2d9ed4123f6b9d4bf58 OK
2022/01/19 05:15:21 INFO  : one: Copied (new)
2022/01/19 05:15:21 DEBUG : Waiting for deletions to finish
2022/01/19 05:15:22 INFO  : three.txt: Deleted
2022/01/19 05:15:23 INFO  : three.txt: Moved (server-side)
2022/01/19 05:15:23 INFO  : three.txt: Moved into backup dir
2022/01/19 05:15:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:15:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:15:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/19 05:15:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:15:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:15:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
--- PASS: TestSyncBackupDir (28.61s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:15:32 DEBUG : dst/one: md5 = 15ff8460dd11010f3467791a89b44533 OK
2022/01/19 05:15:33 DEBUG : dst/two: md5 = 46217b2f8ea112a378b52c45851f82d2 OK
2022/01/19 05:15:35 DEBUG : dst/three.txt: md5 = 31a5bf95926ad6eb552ca412d0dc5049 OK
2022/01/19 05:15:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:15:36 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:15:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/backup"
2022/01/19 05:15:37 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/1nrff024r7pq65ecp72fc28jb0"
2022/01/19 05:15:39 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/19 05:15:39 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:15:39 DEBUG : two: Unchanged skipping
2022/01/19 05:15:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:15:41 INFO  : one: Moved (server-side) to: one.bak
2022/01/19 05:15:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:15:42 DEBUG : one: md5 = 47423d04f3e691b2190f60d669405828 OK
2022/01/19 05:15:42 INFO  : one: Copied (new)
2022/01/19 05:15:42 DEBUG : Waiting for deletions to finish
2022/01/19 05:15:43 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/19 05:15:43 INFO  : three.txt: Moved into backup dir
2022/01/19 05:15:43 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:15:43 DEBUG : pacer: Rate limited, increasing sleep to 1.25701669s
2022/01/19 05:15: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)
2022/01/19 05:15:44 DEBUG : pacer: Rate limited, increasing sleep to 2.278805719s
2022/01/19 05:15:45 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:15:49 DEBUG : dst/three.txt: md5 = a3ee1911857b5ffd1360bf1f629728b6 OK
2022/01/19 05:15:50 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/19 05:15:50 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:15:50 DEBUG : two: Unchanged skipping
2022/01/19 05:15:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:15:51 INFO  : one.bak: Deleted
2022/01/19 05:15:52 INFO  : one: Moved (server-side) to: one.bak
2022/01/19 05:15:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:15:53 DEBUG : one: md5 = 74c78603e807ed1d5f35ae7250c57a9c OK
2022/01/19 05:15:53 INFO  : one: Copied (new)
2022/01/19 05:15:53 DEBUG : Waiting for deletions to finish
2022/01/19 05:15:54 INFO  : three.txt.bak: Deleted
2022/01/19 05:15:55 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/19 05:15:55 INFO  : three.txt: Moved into backup dir
2022/01/19 05:15:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:15:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:16:00 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:16:00 DEBUG : pacer: Rate limited, increasing sleep to 1.421205325s
2022/01/19 05:16:00 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:16:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/19 05:16:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/19 05:16:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/19 05:16:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
--- PASS: TestSyncBackupDirWithSuffix (32.66s)
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:16: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)
2022/01/19 05:16:03 DEBUG : pacer: Rate limited, increasing sleep to 1.617189648s
2022/01/19 05:16:03 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:16:05 DEBUG : dst/one: md5 = 0892a9d20ef1789ac7b97d1e83688daa OK
2022/01/19 05:16:07 DEBUG : dst/two: md5 = 8591ce9d2926dd155fd1fde57089772a OK
2022/01/19 05:16:08 DEBUG : dst/three.txt: md5 = fa0acf1fbad86ffda50233e4a8d6cc42 OK
2022/01/19 05:16:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:16:09 DEBUG : Config file has changed externaly - reloading
2022/01/19 05:16:09 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:16:10 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/backup"
2022/01/19 05:16:10 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/1nrff024r7pq65ecp72fc28jb0"
2022/01/19 05:16:12 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/19 05:16:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:16:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:16:12 DEBUG : two: Unchanged skipping
2022/01/19 05:16:14 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/19 05:16:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:16:16 DEBUG : one: md5 = f3197e2ad0beeb73f7fa7b580ea54343 OK
2022/01/19 05:16:16 INFO  : one: Copied (new)
2022/01/19 05:16:16 DEBUG : Waiting for deletions to finish
2022/01/19 05:16:17 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/19 05:16:17 INFO  : three.txt: Moved into backup dir
2022/01/19 05:16:19 DEBUG : dst/three.txt: md5 = 51e7c8b69fc020f2dd3a5c2518697a40 OK
2022/01/19 05:16:20 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/19 05:16:20 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:16:20 DEBUG : two: Unchanged skipping
2022/01/19 05:16:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:16:21 INFO  : one-2019-01-01: Deleted
2022/01/19 05:16:22 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/19 05:16:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:16:23 DEBUG : one: md5 = 27ac2166bc061cd4ba4ba7cca643b645 OK
2022/01/19 05:16:23 INFO  : one: Copied (new)
2022/01/19 05:16:23 DEBUG : Waiting for deletions to finish
2022/01/19 05:16:24 INFO  : three-2019-01-01.txt: Deleted
2022/01/19 05:16:25 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/19 05:16:25 INFO  : three.txt: Moved into backup dir
2022/01/19 05:16:29 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:16:29 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:16:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/01/19 05:16:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/19 05:16:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/19 05:16:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (29.06s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:16:33 DEBUG : dst/one: md5 = 74ef54caea3d348df5847158999cf2b8 OK
2022/01/19 05:16:35 DEBUG : dst/two: md5 = b85f61127d766c7d4205f18590eb5dee OK
2022/01/19 05:16:36 DEBUG : dst/three.txt: md5 = 6b8698e99c2225d43879e0381f64aa86 OK
2022/01/19 05:16:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:16:37 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:16:38 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/19 05:16:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:16:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:16:38 DEBUG : two: Unchanged skipping
2022/01/19 05:16:39 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:16:39 DEBUG : pacer: Rate limited, increasing sleep to 1.745707851s
2022/01/19 05:16:39 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:16:41 INFO  : one: Moved (server-side) to: one.bak
2022/01/19 05:16:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:16:42 DEBUG : one: md5 = 0b2549a11ea69162c895fc6be1731e00 OK
2022/01/19 05:16:42 INFO  : one: Copied (new)
2022/01/19 05:16:42 DEBUG : Waiting for deletions to finish
2022/01/19 05:16:43 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/19 05:16:43 INFO  : three.txt: Moved into backup dir
2022/01/19 05:16:46 DEBUG : dst/three.txt: md5 = 39d1157528609f21720140a05703748e OK
2022/01/19 05:16:46 DEBUG : three.txt.bak: Excluded
2022/01/19 05:16:46 DEBUG : one.bak: Excluded
2022/01/19 05:16:46 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/19 05:16:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:16:46 DEBUG : two: Unchanged skipping
2022/01/19 05:16:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for checks to finish
2022/01/19 05:16:47 INFO  : one.bak: Deleted
2022/01/19 05:16:48 INFO  : one: Moved (server-side) to: one.bak
2022/01/19 05:16:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst': Waiting for transfers to finish
2022/01/19 05:16:49 DEBUG : one: md5 = 183aaac8034fc2676e18dcaae0c8bb13 OK
2022/01/19 05:16:49 INFO  : one: Copied (new)
2022/01/19 05:16:49 DEBUG : Waiting for deletions to finish
2022/01/19 05:16:50 INFO  : three.txt.bak: Deleted
2022/01/19 05:16:51 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/19 05:16:51 INFO  : three.txt: Moved into backup dir
2022/01/19 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/19 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/19 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/19 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/19 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncBackupDirSuffixOnly (25.05s)
=== RUN   TestSyncSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:16:59 DEBUG : dst/one: md5 = 4f8383e764cea25d2a777660ce3420b2 OK
2022/01/19 05:17:00 DEBUG : dst/two: md5 = 467117eb8dc2147ce10f1d42d0fdcc4c OK
2022/01/19 05:17:02 DEBUG : dst/three.txt: md5 = da367ab3c0be8825b1b5bd8c042d3e51 OK
2022/01/19 05:17:02 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:17:02 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:17:04 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/19 05:17:05 INFO  : one: Moved (server-side) to: one.bak
2022/01/19 05:17:06 DEBUG : one: md5 = c4eb729681e4aec3da0bde34d8fb2522 OK
2022/01/19 05:17:06 INFO  : one: Copied (new)
2022/01/19 05:17:06 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:17:06 DEBUG : two: Unchanged skipping
2022/01/19 05:17:07 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2022/01/19 05:17:07 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/19 05:17:09 DEBUG : three.txt: md5 = 0e360a6f550ff3eb829214324fbc0009 OK
2022/01/19 05:17:09 INFO  : three.txt: Copied (new)
2022/01/19 05:17:11 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/19 05:17:12 INFO  : one.bak: Deleted
2022/01/19 05:17:12 INFO  : one: Moved (server-side) to: one.bak
2022/01/19 05:17:14 DEBUG : one: md5 = d99c40fdeb708c7fb5ffaa5b75f99c9c OK
2022/01/19 05:17:14 INFO  : one: Copied (new)
2022/01/19 05:17:14 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:17:14 DEBUG : two: Unchanged skipping
2022/01/19 05:17:14 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2022/01/19 05:17:15 INFO  : three.txt.bak: Deleted
2022/01/19 05:17:16 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/19 05:17:17 DEBUG : three.txt: md5 = 1dc7ca1aeab703a87ed8db135ec97654 OK
2022/01/19 05:17:17 INFO  : three.txt: Copied (new)
2022/01/19 05:17:19 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:17:19 DEBUG : pacer: Rate limited, increasing sleep to 1.987478571s
2022/01/19 05:17:20 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/19 05:17:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
--- PASS: TestSyncSuffix (29.20s)
=== RUN   TestSyncSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:17:28 DEBUG : dst/one: md5 = 0e1f3d35fd4ba79c0a0a2c65627c0e0b OK
2022/01/19 05:17:29 DEBUG : dst/two: md5 = 66ba85ecdd8cd29225d33c1953720c9a OK
2022/01/19 05:17:31 DEBUG : dst/three.txt: md5 = bde0c1e77145221da080a5ce0796e9d6 OK
2022/01/19 05:17:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jasabit5helogix9levinag2/dst"
2022/01/19 05:17:31 DEBUG : Creating backend with remote "TestDrive:crypt/akd9b35q0m3nf04fgkn9jsd923r2degcomi981q12n4trkavler1pi8ic6osffof03e67sploic0q/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/19 05:17:33 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/19 05:17:34 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/19 05:17:35 DEBUG : one: md5 = 6ae08e2801a0a889d14c56b19d5a9898 OK
2022/01/19 05:17:35 INFO  : one: Copied (new)
2022/01/19 05:17:35 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:17:35 DEBUG : two: Unchanged skipping
2022/01/19 05:17:36 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2022/01/19 05:17:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:17:36 DEBUG : pacer: Rate limited, increasing sleep to 1.412770376s
2022/01/19 05:17:36 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:17:36 DEBUG : pacer: Rate limited, increasing sleep to 2.661358632s
2022/01/19 05:17:38 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:17:38 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/19 05:17:42 DEBUG : three.txt: md5 = 82e6ca0ff9174f636ef2676bf49e5fcb OK
2022/01/19 05:17:42 INFO  : three.txt: Copied (new)
2022/01/19 05:17:43 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/19 05:17:44 INFO  : one-2019-01-01: Deleted
2022/01/19 05:17:45 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/19 05:17:46 DEBUG : one: md5 = 665bd15d6895cf8f8eb007ce19cd46c4 OK
2022/01/19 05:17:46 INFO  : one: Copied (new)
2022/01/19 05:17:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:17:46 DEBUG : two: Unchanged skipping
2022/01/19 05:17:47 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2022/01/19 05:17:47 INFO  : three-2019-01-01.txt: Deleted
2022/01/19 05:17:48 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/19 05:17:50 DEBUG : three.txt: md5 = d85dbb4695b87fb067a651f752c206c5 OK
2022/01/19 05:17:50 INFO  : three.txt: Copied (new)
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/01/19 05:17:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/19 05:17:55 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:17:55 DEBUG : pacer: Rate limited, increasing sleep to 1.654323998s
2022/01/19 05:17:56 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:17:56 DEBUG : pacer: Rate limited, increasing sleep to 2.084475685s
2022/01/19 05:17:57 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestSyncSuffixKeepExtension (32.20s)
=== RUN   TestSyncUTFNorm
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:18:01 DEBUG : Testêé: md5 = 439a58e775879c38f8b9628ca14cb975 OK
2022/01/19 05:18:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:18:01 DEBUG : Testêé: Sizes differ (src 14 vs dst 18)
2022/01/19 05:18:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:18:02 DEBUG : Testêé: md5 = 55e9f0051afa20b69a31f840e7dec8ed OK
2022/01/19 05:18:02 INFO  : Testêé: Copied (replaced existing)
2022/01/19 05:18:02 DEBUG : Waiting for deletions to finish
2022/01/19 05:18: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)
2022/01/19 05:18:03 DEBUG : pacer: Rate limited, increasing sleep to 1.338584117s
2022/01/19 05:18:03 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestSyncUTFNorm (8.57s)
=== RUN   TestSyncImmutable
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:18: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)
2022/01/19 05:18:06 DEBUG : pacer: Rate limited, increasing sleep to 1.526717069s
2022/01/19 05:18:06 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:18:06 DEBUG : pacer: Rate limited, increasing sleep to 2.270813299s
2022/01/19 05:18:08 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:18:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:18:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:18:12 DEBUG : existing: md5 = a97adfe1bc879df9b29755c6a18e54f4 OK
2022/01/19 05:18:12 INFO  : existing: Copied (new)
2022/01/19 05:18:12 DEBUG : Waiting for deletions to finish
2022/01/19 05:18:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:18:13 DEBUG : existing: Sizes differ (src 8 vs dst 6)
2022/01/19 05:18:13 ERROR : existing: Source and destination exist but do not match: immutable file modified
2022/01/19 05:18:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:18:13 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': not deleting files as there were IO errors
2022/01/19 05:18:13 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': not deleting directories as there were IO errors
--- PASS: TestSyncImmutable (8.19s)
=== RUN   TestSyncIgnoreCase
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:18:16 DEBUG : EXISTING: md5 = 4086e4208f588d76c9f457991eaf06c8 OK
2022/01/19 05:18:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:18:16 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:18:16 DEBUG : existing: Unchanged skipping
2022/01/19 05:18:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:18:16 DEBUG : Waiting for deletions to finish
2022/01/19 05:18:16 INFO  : There was nothing to transfer
2022/01/19 05:18:18 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:18:18 DEBUG : pacer: Rate limited, increasing sleep to 1.716684646s
2022/01/19 05:18:18 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestSyncIgnoreCase (3.72s)
=== RUN   TestMaxTransfer
=== RUN   TestMaxTransfer/Hard
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", 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-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", 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-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
    sync_test.go:1989: This test only runs on local
--- PASS: TestMaxTransfer (3.17s)
    --- SKIP: TestMaxTransfer/Hard (1.99s)
    --- SKIP: TestMaxTransfer/Soft (0.56s)
    --- SKIP: TestMaxTransfer/Cautious (0.62s)
=== RUN   TestSyncConcurrentDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:18:22 DEBUG : both0: md5 = edf5b96df200904adc923b144c68272c OK
2022/01/19 05:18:25 DEBUG : only0: md5 = a2cb9204a6d03b1dc5f882f5eb625cfd OK
2022/01/19 05:18:27 DEBUG : both1: md5 = 29d5455dd02bf41ec5534959a6bbbc68 OK
2022/01/19 05:18:28 DEBUG : only1: md5 = 21713b5cc56c671e61f0e2d97fd69710 OK
2022/01/19 05:18:31 DEBUG : both2: md5 = 8e892d683634b7d5ef2da6cf7859e7ce OK
2022/01/19 05:18:32 DEBUG : only2: md5 = c235c6a7a8c96b771b36b976d2514447 OK
2022/01/19 05:18:34 DEBUG : both3: md5 = 04446d015d11deae5421d4f0dd4473bb OK
2022/01/19 05:18:36 DEBUG : only3: md5 = 78e9b4f2025dae797202f823582ddd8c OK
2022/01/19 05:18:37 DEBUG : both4: md5 = 75c81b8308c591e47f5c1c3e6b308078 OK
2022/01/19 05:18:39 DEBUG : only4: md5 = 7bc55d72570709581d8054d81171a24a OK
2022/01/19 05:18:40 DEBUG : both5: md5 = f4ee18a06a526da25547fa7ea9b9885f OK
2022/01/19 05:18:43 DEBUG : only5: md5 = ba2df8f8b87c7d21c343b7096173b352 OK
2022/01/19 05:18:44 DEBUG : both6: md5 = a719668a00006e58681429b3084c7c0b OK
2022/01/19 05:18:46 DEBUG : only6: md5 = 3caed1ad7ab73b2d34002b20fb25bd15 OK
2022/01/19 05:18:48 DEBUG : both7: md5 = 655698874cb5c891222529e0bb6c0f59 OK
2022/01/19 05:18:49 DEBUG : only7: md5 = a9f7169bb637524534c8e4b2b1198faa OK
2022/01/19 05:18:51 DEBUG : both8: md5 = 3b6e4e1181149b78dd7850b8f1002bf9 OK
2022/01/19 05:18:53 DEBUG : only8: md5 = d930843d9b0a8434c09d5a4258b7eb23 OK
2022/01/19 05:18:55 DEBUG : both9: md5 = f2818305c9ad823ea80ba331236ac9ca OK
2022/01/19 05:18:56 DEBUG : only9: md5 = 402a164f09a69a47e561d7e494aa5471 OK
2022/01/19 05:18:59 DEBUG : both10: md5 = d3ac733cf2e34885c8621fa4a5147643 OK
2022/01/19 05:19:00 DEBUG : only10: md5 = 4b44b2f24efda815fb6ec09b0a108a47 OK
2022/01/19 05:19:01 DEBUG : both11: md5 = bfccf39c4a122025a44ae6a38a687842 OK
2022/01/19 05:19:03 DEBUG : only11: md5 = 0f5cef0dc0007515fcdb2cb1d5e1f27e OK
2022/01/19 05:19:04 DEBUG : both12: md5 = daca15d41ab76184f615ed31c8b44e48 OK
2022/01/19 05:19:06 DEBUG : only12: md5 = e23fb83825a7b772802193eb3f27ab64 OK
2022/01/19 05:19:07 DEBUG : both13: md5 = 642016e7ed03ae9fe28978854d5c9893 OK
2022/01/19 05:19:11 DEBUG : only13: md5 = 6de8d1949dcedd64c257bb0a1f409074 OK
2022/01/19 05:19:12 DEBUG : both14: md5 = 17f69660184df2f226bd9d386c2846d5 OK
2022/01/19 05:19:15 DEBUG : only14: md5 = 0a2c545ee935592892ae6391e04c0973 OK
2022/01/19 05:19:16 DEBUG : both15: md5 = b3cc54793b9a96bc7d60a894d6cfeb48 OK
2022/01/19 05:19:17 DEBUG : only15: md5 = a3813fa95bef621f74c81ebc5cdf4aa8 OK
2022/01/19 05:19:21 DEBUG : both16: md5 = 291ba58667b61022d9ac2635ecfd9fae OK
2022/01/19 05:19:22 DEBUG : only16: md5 = 100561ee8a70ca47fe4f59183c760562 OK
2022/01/19 05:19:24 DEBUG : both17: md5 = 2c0f23048236d53cef02d78aef384bd7 OK
2022/01/19 05:19:26 DEBUG : only17: md5 = 6d45dd7cf7a6b3e0611a80013f9e0c2a OK
2022/01/19 05:19:29 DEBUG : both18: md5 = ad194ab99d07e6482d55cda7090e188b OK
2022/01/19 05:19:30 DEBUG : only18: md5 = 997664e008b9c77167d75de3ca3ac774 OK
2022/01/19 05:19:32 DEBUG : both19: md5 = dd245f4781517a5a70dd0853214481af OK
2022/01/19 05:19:33 DEBUG : only19: md5 = 9e8992894f1c801e91235d5fbf6a70ad OK
2022/01/19 05:19:34 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both0: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both1: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both12: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both13: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both14: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both16: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both11: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both17: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both15: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:19:34 DEBUG : both18: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both3: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both4: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both5: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both6: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both7: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both8: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both9: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both19: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both2: Unchanged skipping
2022/01/19 05:19:34 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:19:34 DEBUG : both10: Unchanged skipping
2022/01/19 05:19:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:19:34 DEBUG : Waiting for deletions to finish
2022/01/19 05:19:35 INFO  : only6: Deleted
2022/01/19 05:19:35 INFO  : only9: Deleted
2022/01/19 05:19:35 INFO  : only19: Deleted
2022/01/19 05:19:35 INFO  : only15: Deleted
2022/01/19 05:19:35 INFO  : only8: Deleted
2022/01/19 05:19:35 INFO  : only18: Deleted
2022/01/19 05:19:35 INFO  : only7: Deleted
2022/01/19 05:19:35 INFO  : only2: Deleted
2022/01/19 05:19:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:19:36 DEBUG : pacer: Rate limited, increasing sleep to 1.431988424s
2022/01/19 05:19:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:19:36 DEBUG : pacer: Rate limited, increasing sleep to 2.910881351s
2022/01/19 05:19:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:19:36 DEBUG : pacer: Rate limited, increasing sleep to 4.861280659s
2022/01/19 05:19:36 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:19:36 INFO  : only0: Deleted
2022/01/19 05:19:36 INFO  : only13: Deleted
2022/01/19 05:19:37 INFO  : only5: Deleted
2022/01/19 05:19:38 INFO  : only14: Deleted
2022/01/19 05:19:38 INFO  : only17: Deleted
2022/01/19 05:19:38 INFO  : only12: Deleted
2022/01/19 05:19:39 INFO  : only3: Deleted
2022/01/19 05:19:39 INFO  : only11: Deleted
2022/01/19 05:19:39 INFO  : only1: Deleted
2022/01/19 05:19:39 INFO  : only16: Deleted
2022/01/19 05:19:40 INFO  : only4: Deleted
2022/01/19 05:19:40 INFO  : only10: Deleted
2022/01/19 05:19:40 INFO  : There was nothing to transfer
2022/01/19 05:19:41 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:19:41 DEBUG : pacer: Rate limited, increasing sleep to 1.430959573s
2022/01/19 05:19:41 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestSyncConcurrentDelete (95.20s)
=== RUN   TestSyncConcurrentTruncate
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2'", Local "Local file system at /tmp/rclone1673842480", Modify Window "1ms"
2022/01/19 05:19:56 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:19:56 DEBUG : pacer: Rate limited, increasing sleep to 1.60729194s
2022/01/19 05:19:56 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/19 05:19:56 DEBUG : pacer: Rate limited, increasing sleep to 2.59794326s
2022/01/19 05:19:58 DEBUG : pacer: Reducing sleep to 0s
2022/01/19 05:20:02 DEBUG : both0: md5 = b840e87349696733a6f723c20825a33f OK
2022/01/19 05:20:03 DEBUG : only0: md5 = e2d45177b184148da57e9b5fe0fac4e6 OK
2022/01/19 05:20:05 DEBUG : both1: md5 = 97b748f48e354d07238c6931bb944940 OK
2022/01/19 05:20:06 DEBUG : only1: md5 = 648c52bb875d5c4433678196b11e9680 OK
2022/01/19 05:20:08 DEBUG : both2: md5 = edafe121b57f2d0a29b3800b8598e558 OK
2022/01/19 05:20:09 DEBUG : only2: md5 = 3450e2c335f58e4ae0318b42130410eb OK
2022/01/19 05:20:11 DEBUG : both3: md5 = e0e88feeedc31eba805adfaf9fea2498 OK
2022/01/19 05:20:12 DEBUG : only3: md5 = e17b9daf035dc250b149709ebb1415e0 OK
2022/01/19 05:20:14 DEBUG : both4: md5 = 6b9073adfdf209e7e8f6121eca8f4ac4 OK
2022/01/19 05:20:15 DEBUG : only4: md5 = 915035c01bbe5bf46fc54df18248dcd6 OK
2022/01/19 05:20:17 DEBUG : both5: md5 = 90f82f225adc5c61c6706a3b282c2c68 OK
2022/01/19 05:20:19 DEBUG : only5: md5 = 44ce81a1602b203d347c8e6829ab6f11 OK
2022/01/19 05:20:20 DEBUG : both6: md5 = edf18408b954c40c10aa8b9e0d8965d1 OK
2022/01/19 05:20:23 DEBUG : only6: md5 = 6c32374ecaa2a585e25139d2a1db248b OK
2022/01/19 05:20:25 DEBUG : both7: md5 = 6c8d7111b794b06925911b632ede3ede OK
2022/01/19 05:20:26 DEBUG : only7: md5 = e016bee440c72157a2612ef18f0cec79 OK
2022/01/19 05:20:28 DEBUG : both8: md5 = 9e5bf5c8185941e6458229ed365cec0d OK
2022/01/19 05:20:30 DEBUG : only8: md5 = 54a1181313660ca90b57dd61fd290c41 OK
2022/01/19 05:20:31 DEBUG : both9: md5 = b316eaa584a06df20f3ba9343514664d OK
2022/01/19 05:20:33 DEBUG : only9: md5 = 7867adb2b16e5bcf5e1325161be3cc2d OK
2022/01/19 05:20:35 DEBUG : both10: md5 = 73d24ac498e0a03364da1f05df78661e OK
2022/01/19 05:20:36 DEBUG : only10: md5 = cfac90ef9d59e95771c48b6f64223bc2 OK
2022/01/19 05:20:38 DEBUG : both11: md5 = 367c97a2e019e826594465065ea3dce5 OK
2022/01/19 05:20:39 DEBUG : only11: md5 = d8006bc4ad530d09735855988982842c OK
2022/01/19 05:20:41 DEBUG : both12: md5 = 2d3fe2647868cf1c15d1ccd01854a747 OK
2022/01/19 05:20:42 DEBUG : only12: md5 = 71e63bc8a5b061d6eba657766a43b164 OK
2022/01/19 05:20:44 DEBUG : both13: md5 = 9ecebbbd7821d64c01598890f257fd2a OK
2022/01/19 05:20:46 DEBUG : only13: md5 = 7dc7cc97a7dc1115f7064bbb3cb39d90 OK
2022/01/19 05:20:48 DEBUG : both14: md5 = 30c0919fcef12488dd31972b2965ef96 OK
2022/01/19 05:20:49 DEBUG : only14: md5 = 50e98e1b7c4fc65119b5bb859892ff18 OK
2022/01/19 05:20:51 DEBUG : both15: md5 = 032bf4109ebf39db94327773f3efd423 OK
2022/01/19 05:20:52 DEBUG : only15: md5 = 34f8e74e0dc077a07d27632b40896d11 OK
2022/01/19 05:20:54 DEBUG : both16: md5 = 9530b547679f587ee154a08b2ca13adb OK
2022/01/19 05:20:56 DEBUG : only16: md5 = b263ef6c091fd4f0427073527adf1843 OK
2022/01/19 05:20:57 DEBUG : both17: md5 = 1553225449a331c162fb3b776f56f241 OK
2022/01/19 05:20:58 DEBUG : only17: md5 = ab28a45aec97a7a8ad6593675a1db2da OK
2022/01/19 05:21:00 DEBUG : both18: md5 = e0406636858aadffa3370359f485dbd1 OK
2022/01/19 05:21:01 DEBUG : only18: md5 = 9e94f23fd5ce9c9a084b0afac970bcef OK
2022/01/19 05:21:03 DEBUG : both19: md5 = cce3ff4a9fa95fb2748d2c5ea98e67eb OK
2022/01/19 05:21:04 DEBUG : only19: md5 = b14c024108ea93e15bf590dd5499c5b2 OK
2022/01/19 05:21:05 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both11: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for checks to finish
2022/01/19 05:21:05 DEBUG : both10: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both13: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both14: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both15: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both16: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both17: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both12: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both18: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both1: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both3: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both4: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both5: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both6: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both7: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both8: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both9: Unchanged skipping
2022/01/19 05:21:05 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : both2: Unchanged skipping
2022/01/19 05:21:05 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/19 05:21:05 DEBUG : both0: Unchanged skipping
2022/01/19 05:21:05 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : both19: Unchanged skipping
2022/01/19 05:21:05 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2022/01/19 05:21:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Waiting for transfers to finish
2022/01/19 05:21:06 DEBUG : only11: md5 = 52dc70ff736a1392be722349a4f15f71 OK
2022/01/19 05:21:06 INFO  : only11: Copied (replaced existing)
2022/01/19 05:21:06 DEBUG : only10: md5 = e8f0f24dd4b6167f78e0950f4aa4ae60 OK
2022/01/19 05:21:06 INFO  : only10: Copied (replaced existing)
2022/01/19 05:21:06 DEBUG : only0: md5 = a6aea8fa8973d57eda5cac914dfa435a OK
2022/01/19 05:21:06 INFO  : only0: Copied (replaced existing)
2022/01/19 05:21:06 DEBUG : only1: md5 = a7525721dd7c0dcec31ecb18cc49f2b0 OK
2022/01/19 05:21:06 INFO  : only1: Copied (replaced existing)
2022/01/19 05:21:07 DEBUG : only14: md5 = 90c4e9f4c3100cd12a5edd9c156e32c1 OK
2022/01/19 05:21:07 INFO  : only14: Copied (replaced existing)
2022/01/19 05:21:07 DEBUG : only15: md5 = 50bc033527e3de12a5da62deafadd4d8 OK
2022/01/19 05:21:07 INFO  : only15: Copied (replaced existing)
2022/01/19 05:21:07 DEBUG : only16: md5 = f2444a9a877ccfd22f114b896278ed17 OK
2022/01/19 05:21:07 INFO  : only16: Copied (replaced existing)
2022/01/19 05:21:07 DEBUG : only17: md5 = ca1bc633b95c9044d019cf9fb9244b4d OK
2022/01/19 05:21:07 INFO  : only17: Copied (replaced existing)
2022/01/19 05:21:08 DEBUG : only19: md5 = d2a7b9afb4d73d489568a742133e6884 OK
2022/01/19 05:21:08 INFO  : only19: Copied (replaced existing)
2022/01/19 05:21:09 DEBUG : only2: md5 = d793675d0cf44c892164fb451f30b4ec OK
2022/01/19 05:21:09 INFO  : only2: Copied (replaced existing)
2022/01/19 05:21:09 DEBUG : only3: md5 = 421b5f0e3836f97e449555c890b7d5b6 OK
2022/01/19 05:21:09 INFO  : only3: Copied (replaced existing)
2022/01/19 05:21:09 DEBUG : only4: md5 = d8b6a6ed541b646c0887c19dc79b6221 OK
2022/01/19 05:21:09 INFO  : only4: Copied (replaced existing)
2022/01/19 05:21:10 DEBUG : only5: md5 = 4748ef42acf02aad7a9fab552f5c1cdb OK
2022/01/19 05:21:10 INFO  : only5: Copied (replaced existing)
2022/01/19 05:21:10 DEBUG : only6: md5 = 13bedb2b43c6be43db699b515304f0ad OK
2022/01/19 05:21:10 INFO  : only6: Copied (replaced existing)
2022/01/19 05:21:10 DEBUG : only7: md5 = cc0cf26d855afb7f7b96d042c4c0e19a OK
2022/01/19 05:21:10 INFO  : only7: Copied (replaced existing)
2022/01/19 05:21:10 DEBUG : only8: md5 = 416e80e34ebd7b42692de0f60dcea197 OK
2022/01/19 05:21:10 INFO  : only8: Copied (replaced existing)
2022/01/19 05:21:11 DEBUG : only13: md5 = 49436ff4412bfe14258a04f901e383f4 OK
2022/01/19 05:21:11 INFO  : only13: Copied (replaced existing)
2022/01/19 05:21:11 DEBUG : only18: md5 = 75ff44de2af44784b971b02e6e1954ca OK
2022/01/19 05:21:11 INFO  : only18: Copied (replaced existing)
2022/01/19 05:21:11 DEBUG : only9: md5 = 1705aa2707138df4013fb617044edd8f OK
2022/01/19 05:21:11 INFO  : only9: Copied (replaced existing)
2022/01/19 05:21:11 DEBUG : only12: md5 = 7a8d09dcb29f12d284b93e2c294cf7cd OK
2022/01/19 05:21:11 INFO  : only12: Copied (replaced existing)
2022/01/19 05:21:11 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncConcurrentTruncate (104.16s)
PASS
2022/01/19 05:21:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jasabit5helogix9levinag2': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Finished OK in 14m34.920225465s (try 1/5)