"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5)
2022/01/17 05:16:45 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4"
2022/01/17 05:16:45 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/01/17 05:16:45 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm"
2022/01/17 05:16:47 DEBUG : Creating backend with remote "/tmp/rclone107662796"
=== RUN   TestPipe
--- PASS: TestPipe (0.00s)
=== RUN   TestPipeConcurrent
--- PASS: TestPipeConcurrent (0.03s)
=== RUN   TestPipeOrderBy
=== RUN   TestPipeOrderBy/#00
=== RUN   TestPipeOrderBy/size
=== RUN   TestPipeOrderBy/name
=== RUN   TestPipeOrderBy/modtime
=== RUN   TestPipeOrderBy/size,ascending
=== RUN   TestPipeOrderBy/name,asc
=== RUN   TestPipeOrderBy/modtime,ascending
=== RUN   TestPipeOrderBy/size,descending
=== RUN   TestPipeOrderBy/name,desc
=== RUN   TestPipeOrderBy/modtime,descending
=== RUN   TestPipeOrderBy/size,mixed,50
=== RUN   TestPipeOrderBy/size,mixed,51
--- PASS: TestPipeOrderBy (0.00s)
    --- PASS: TestPipeOrderBy/#00 (0.00s)
    --- PASS: TestPipeOrderBy/size (0.00s)
    --- PASS: TestPipeOrderBy/name (0.00s)
    --- PASS: TestPipeOrderBy/modtime (0.00s)
    --- PASS: TestPipeOrderBy/size,ascending (0.00s)
    --- PASS: TestPipeOrderBy/name,asc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,ascending (0.00s)
    --- PASS: TestPipeOrderBy/size,descending (0.00s)
    --- PASS: TestPipeOrderBy/name,desc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,descending (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s)
=== RUN   TestNewLess
=== RUN   TestNewLess/blankOK
=== RUN   TestNewLess/tooManyParts
=== RUN   TestNewLess/tooManyParts2
=== RUN   TestNewLess/badMixed
=== RUN   TestNewLess/unknownComparison
=== RUN   TestNewLess/unknownSortDirection
=== RUN   TestNewLess/size
=== RUN   TestNewLess/name
=== RUN   TestNewLess/modtime
=== RUN   TestNewLess/size,ascending
=== RUN   TestNewLess/name,asc
=== RUN   TestNewLess/modtime,ascending
=== RUN   TestNewLess/size,descending
=== RUN   TestNewLess/name,desc
=== RUN   TestNewLess/modtime,descending
=== RUN   TestNewLess/modtime,mixed
=== RUN   TestNewLess/modtime,mixed,30
--- PASS: TestNewLess (0.00s)
    --- PASS: TestNewLess/blankOK (0.00s)
    --- PASS: TestNewLess/tooManyParts (0.00s)
    --- PASS: TestNewLess/tooManyParts2 (0.00s)
    --- PASS: TestNewLess/badMixed (0.00s)
    --- PASS: TestNewLess/unknownComparison (0.00s)
    --- PASS: TestNewLess/unknownSortDirection (0.00s)
    --- PASS: TestNewLess/size (0.00s)
    --- PASS: TestNewLess/name (0.00s)
    --- PASS: TestNewLess/modtime (0.00s)
    --- PASS: TestNewLess/size,ascending (0.00s)
    --- PASS: TestNewLess/name,asc (0.00s)
    --- PASS: TestNewLess/modtime,ascending (0.00s)
    --- PASS: TestNewLess/size,descending (0.00s)
    --- PASS: TestNewLess/name,desc (0.00s)
    --- PASS: TestNewLess/modtime,descending (0.00s)
    --- PASS: TestNewLess/modtime,mixed (0.00s)
    --- PASS: TestNewLess/modtime,mixed,30 (0.00s)
=== RUN   TestRcCopy
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcCopy (0.00s)
=== RUN   TestRcMove
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcMove (0.00s)
=== RUN   TestRcSync
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcSync (0.00s)
=== RUN   TestCopyWithDryRun
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:16:48 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2022/01/17 05:16:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:16:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
--- PASS: TestCopyWithDryRun (2.00s)
=== RUN   TestCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:16:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:16:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:16:52 DEBUG : sub dir/hello world: md5 = 03f526aed7f04fc32e83859deb4541aa OK
2022/01/17 05:16:52 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:16:54 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopy (5.84s)
=== RUN   TestCopyMissingDirectory
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:16:55 DEBUG : Creating backend with remote "/non-existing"
2022/01/17 05:16:55 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2022/01/17 05:16:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:16:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:16: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/17 05:16:55 DEBUG : pacer: Rate limited, increasing sleep to 1.919482716s
2022/01/17 05:16:56 DEBUG : pacer: Reducing sleep to 0s
--- PASS: TestCopyMissingDirectory (0.94s)
=== RUN   TestCopyNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:16:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:16:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:00 DEBUG : sub dir/hello world: md5 = 3fd8572ce3d2c656bc4107a9834f7079 OK
2022/01/17 05:17:00 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:17:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyNoTraverse (7.31s)
=== RUN   TestCopyCheckFirst
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:03 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Running all checks before starting transfers
2022/01/17 05:17:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:03 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Checks finished, now starting transfers
2022/01/17 05:17:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17: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/17 05:17:04 DEBUG : pacer: Rate limited, increasing sleep to 1.012461929s
2022/01/17 05:17:04 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:17:07 DEBUG : sub dir/hello world: md5 = 2745337def94c71ea5fb49c1236b67a5 OK
2022/01/17 05:17:07 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:17:10 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/17 05:17:10 DEBUG : pacer: Rate limited, increasing sleep to 1.030547322s
2022/01/17 05:17:10 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:17:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyCheckFirst (8.32s)
=== RUN   TestSyncNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:11 ERROR : Ignoring --no-traverse with sync
2022/01/17 05:17:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:15 DEBUG : sub dir/hello world: md5 = 8ecddd01bada17926794515de4748ce6 OK
2022/01/17 05:17:15 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:17:15 DEBUG : Waiting for deletions to finish
2022/01/17 05:17:17 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncNoTraverse (6.66s)
=== RUN   TestCopyWithDepth
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:20 DEBUG : hello world2: md5 = 42b5aa8f68f966009ba0bd6727fd51d9 OK
2022/01/17 05:17:20 INFO  : hello world2: Copied (new)
--- PASS: TestCopyWithDepth (3.42s)
=== RUN   TestCopyWithFilesFrom
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:22 DEBUG : hello world2: Excluded
2022/01/17 05:17:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:23 DEBUG : potato2: md5 = cd5f4dfb506dc852672dd4df7f274d0c OK
2022/01/17 05:17:23 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFrom (3.46s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:27 DEBUG : potato2: md5 = 01fa2cb29971948896e92b6a198b69d6 OK
2022/01/17 05:17:27 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFromAndNoTraverse (3.48s)
=== RUN   TestCopyEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:28 DEBUG : sub dir2: Making directory
2022/01/17 05:17:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:32 DEBUG : sub dir/hello world: md5 = 2f04f818bdb9a74e242637a0cfaecad4 OK
2022/01/17 05:17:32 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:17:32 DEBUG : sub dir2: Making directory
2022/01/17 05:17:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': copied 1 directories
2022/01/17 05:17:36 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyEmptyDirectories (8.41s)
=== RUN   TestMoveEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:37 DEBUG : sub dir2: Making directory
2022/01/17 05:17:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:40 DEBUG : sub dir/hello world: md5 = d2f7c91c263de0ff5f02169b7823b73f OK
2022/01/17 05:17:40 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:17:40 INFO  : sub dir/hello world: Deleted
2022/01/17 05:17:40 DEBUG : sub dir: Making directory
2022/01/17 05:17:40 DEBUG : sub dir2: Making directory
2022/01/17 05:17:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': copied 2 directories
2022/01/17 05:17:44 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestMoveEmptyDirectories (8.11s)
=== RUN   TestSyncEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:45 DEBUG : sub dir2: Making directory
2022/01/17 05:17:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:17:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:17:48 DEBUG : sub dir/hello world: md5 = a66c09406cbdf6dbeb64c41bd65f38ed OK
2022/01/17 05:17:48 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:17:48 DEBUG : sub dir2: Making directory
2022/01/17 05:17:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': copied 1 directories
2022/01/17 05:17:49 DEBUG : Waiting for deletions to finish
2022/01/17 05:17:52 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncEmptyDirectories (7.94s)
=== RUN   TestServerSideCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:17:56 DEBUG : sub dir/hello world: md5 = ce451b0c0724b3027ddd70829e81af5c OK
2022/01/17 05:17:56 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-zaqikun9lelekel2qaxesox7"
2022/01/17 05:17:56 DEBUG : Config file has changed externaly - reloading
2022/01/17 05:17:56 DEBUG : Creating backend with remote "TestDrive:crypt/p4rrhnkbt240t878he48bdeshdg859rjgp02f3c07ahm3i0gv38e2ln026se8s415bctf9glru3iq"
    sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4' -> Encrypted drive 'TestCryptDrive:rclone-test-zaqikun9lelekel2qaxesox7'
2022/01/17 05:17:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zaqikun9lelekel2qaxesox7': Waiting for checks to finish
2022/01/17 05:17:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zaqikun9lelekel2qaxesox7': Waiting for transfers to finish
2022/01/17 05:18:02 INFO  : sub dir/hello world: Copied (server-side copy)
2022/01/17 05:18:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zaqikun9lelekel2qaxesox7': Purge remote
2022/01/17 05:18:05 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestServerSideCopy (12.60s)
=== RUN   TestCopyAfterDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:08 DEBUG : sub dir/hello world: md5 = 1641ce3c38c7ff943e9ccd6c3583cc0c OK
2022/01/17 05:18:08 ERROR : : error listing: directory not found
2022/01/17 05:18:09 DEBUG : Local file system at /tmp/rclone107662796: Making directory
2022/01/17 05:18:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:12 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyAfterDelete (6.83s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:15 DEBUG : sub dir/hello world: md5 = 582a9457a039149d64f93c6c2ae02c92 OK
2022/01/17 05:18:16 DEBUG : Local file system at /tmp/rclone107662796: Waiting for checks to finish
2022/01/17 05:18:16 DEBUG : Local file system at /tmp/rclone107662796: Waiting for transfers to finish
2022/01/17 05:18:17 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:18:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyRedownload (7.06s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:22 DEBUG : check sum: md5 = 5222031fe3f617a2864b5b2872afe1c8 OK
2022/01/17 05:18:22 INFO  : check sum: Copied (new)
2022/01/17 05:18:22 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:22 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2022/01/17 05:18:22 DEBUG : check sum: Size of src and dst objects identical
2022/01/17 05:18:22 DEBUG : check sum: Unchanged skipping
2022/01/17 05:18:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:22 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:22 INFO  : There was nothing to transfer
--- PASS: TestSyncBasedOnCheckSum (4.36s)
=== RUN   TestSyncSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:26 DEBUG : sizeonly: md5 = cd6a52f18f0e05a99e2a7d88b26ba827 OK
2022/01/17 05:18:26 INFO  : sizeonly: Copied (new)
2022/01/17 05:18:26 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:26 DEBUG : sizeonly: Sizes identical
2022/01/17 05:18:26 DEBUG : sizeonly: Unchanged skipping
2022/01/17 05:18:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:26 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:26 INFO  : There was nothing to transfer
--- PASS: TestSyncSizeOnly (4.06s)
=== RUN   TestSyncIgnoreSize
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:30 DEBUG : ignore-size: md5 = 464f53e1309a869eae7a194d520aed79 OK
2022/01/17 05:18:30 INFO  : ignore-size: Copied (new)
2022/01/17 05:18:30 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:30 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:18:30 DEBUG : ignore-size: Unchanged skipping
2022/01/17 05:18:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:30 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:30 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreSize (3.87s)
=== RUN   TestSyncIgnoreTimes
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:33 DEBUG : existing: md5 = b698392431274e7b23456165f1e8e2d4 OK
2022/01/17 05:18:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:34 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:18:34 DEBUG : existing: Unchanged skipping
2022/01/17 05:18:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:34 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:34 INFO  : There was nothing to transfer
2022/01/17 05:18:34 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2022/01/17 05:18:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:36 DEBUG : existing: md5 = 510ad017c59f928f595c1e19a6f4fce7 OK
2022/01/17 05:18:36 INFO  : existing: Copied (replaced existing)
2022/01/17 05:18:36 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncIgnoreTimes (5.41s)
=== RUN   TestSyncIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:39 DEBUG : existing: md5 = 29dc898086750023986503eedac63f0c OK
2022/01/17 05:18:39 INFO  : existing: Copied (new)
2022/01/17 05:18:39 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:40 DEBUG : existing: Destination exists, skipping
2022/01/17 05:18:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:40 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:40 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreExisting (4.01s)
=== RUN   TestSyncIgnoreErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:18:44 DEBUG : b/potato: md5 = 562b1fd305dccb3cbd9ae513eb8a9869 OK
2022/01/17 05:18:46 DEBUG : c/non empty space: md5 = 3828870b450c3c6a871d68cf467d103d OK
2022/01/17 05:18:46 DEBUG : d: Making directory
2022/01/17 05:18:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:18:49 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:18:49 DEBUG : c/non empty space: Unchanged skipping
2022/01/17 05:18:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:18:51 DEBUG : a/potato2: md5 = 1b346fe038c06b030c19171d558f3926 OK
2022/01/17 05:18:51 INFO  : a/potato2: Copied (new)
2022/01/17 05:18:51 DEBUG : Waiting for deletions to finish
2022/01/17 05:18:52 INFO  : b/potato: Deleted
2022/01/17 05:18:52 INFO  : d: Removing directory
2022/01/17 05:18:53 INFO  : b: Removing directory
2022/01/17 05:18:53 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/01/17 05:18:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': deleted 2 directories
2022/01/17 05:18:57 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/01/17 05:18:57 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncIgnoreErrors (17.25s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:00 DEBUG : empty space: md5 = 63f8864db35de935fb85ecb846a764fc OK
2022/01/17 05:19:01 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/17 05:19:01 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2022/01/17 05:19:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:01 DEBUG : Waiting for deletions to finish
2022/01/17 05:19:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:01 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/17 05:19:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:02 DEBUG : empty space: md5 = 258b37d58fa37761378bf5ca31d7cc8c OK
2022/01/17 05:19:02 INFO  : empty space: Copied (replaced existing)
2022/01/17 05:19:02 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingModtimeOnly (5.48s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
    sync_test.go:577: Can't check this if no hashes supported
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.50s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:06 DEBUG : foo: md5 = 46942c04f0a7685fd1c895ffc64ca08b OK
2022/01/17 05:19:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:07 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/17 05:19:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:08 DEBUG : foo: md5 = 7bba7d4695f478d24f2118e3ae658560 OK
2022/01/17 05:19:08 INFO  : foo: Copied (replaced existing)
2022/01/17 05:19:08 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncDoesntUpdateModtime (5.59s)
=== RUN   TestSyncAfterAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:12 DEBUG : empty space: md5 = ed19ce3f82d2b162c91ce4b4f0eb0ec3 OK
2022/01/17 05:19:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:12 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:19:12 DEBUG : empty space: Unchanged skipping
2022/01/17 05:19:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:14 DEBUG : potato: md5 = ade61ab4d105ad451cce75aa37695f7d OK
2022/01/17 05:19:14 INFO  : potato: Copied (new)
2022/01/17 05:19:14 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterAddingAFile (5.92s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:18 DEBUG : potato: md5 = be39d1ca58281a6196857ec897b49152 OK
2022/01/17 05:19:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:18 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2022/01/17 05:19:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:19 DEBUG : potato: md5 = 1d5b10954e5e5f02950f1a8e43f608c5 OK
2022/01/17 05:19:19 INFO  : potato: Copied (replaced existing)
2022/01/17 05:19:19 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingFilesSizeOnly (4.87s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:22 DEBUG : potato: md5 = 9f608bf6de053403aac1862129a36fe3 OK
2022/01/17 05:19:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:23 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/17 05:19:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:24 DEBUG : potato: md5 = 2b771d9a9ae416aaf4f538d475e9f762 OK
2022/01/17 05:19:24 INFO  : potato: Copied (replaced existing)
2022/01/17 05:19:24 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingContentsOnly (4.77s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:27 DEBUG : potato: md5 = cba099d451825e0f3206e87807de068f OK
2022/01/17 05:19:29 DEBUG : empty space: md5 = 69f7ab14ffea362c9a18852d2efe7802 OK
2022/01/17 05:19:30 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2022/01/17 05:19:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:30 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:19:30 DEBUG : empty space: Unchanged skipping
2022/01/17 05:19:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:30 DEBUG : Waiting for deletions to finish
2022/01/17 05:19:30 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (6.24s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:33 DEBUG : potato: md5 = 9b8a4530c9ec34c1f7b7d8a97c0a173c OK
2022/01/17 05:19:35 DEBUG : empty space: md5 = cfeb853e17869c2b94404cbbfc59d472 OK
2022/01/17 05:19:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:35 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:19:35 DEBUG : empty space: Unchanged skipping
2022/01/17 05:19:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:37 DEBUG : potato2: md5 = ac65507c771ee742da7eafd6e018d51d OK
2022/01/17 05:19:37 INFO  : potato2: Copied (new)
2022/01/17 05:19:37 DEBUG : Waiting for deletions to finish
2022/01/17 05:19:38 INFO  : potato: Deleted
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.95s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:19:42 DEBUG : b/potato: md5 = 36cee5b399fbf93bab3f318d10ae78d1 OK
2022/01/17 05:19:45 DEBUG : c/non empty space: md5 = 6dc492a532c57f8db5d88674dab58459 OK
2022/01/17 05:19:45 DEBUG : d: Making directory
2022/01/17 05:19:46 DEBUG : d/e: Making directory
2022/01/17 05:19:49 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:19:49 DEBUG : c/non empty space: Unchanged skipping
2022/01/17 05:19:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:19:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:19:51 DEBUG : a/potato2: md5 = cb706ea733e962ac317bfb299f3c83d7 OK
2022/01/17 05:19:51 INFO  : a/potato2: Copied (new)
2022/01/17 05:19:51 DEBUG : Waiting for deletions to finish
2022/01/17 05:19:51 INFO  : b/potato: Deleted
2022/01/17 05:19:51 INFO  : d/e: Removing directory
2022/01/17 05:19:52 INFO  : d: Removing directory
2022/01/17 05:19:53 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8"
2022/01/17 05:19:53 INFO  : b: Removing directory
2022/01/17 05:19:54 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/01/17 05:19:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': deleted 3 directories
2022/01/17 05:19:57 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/01/17 05:19:58 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (19.45s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:02 DEBUG : b/potato: md5 = 358eeed3a720282f227bd19b6d37897d OK
2022/01/17 05:20:04 DEBUG : c/non empty space: md5 = f25f8fafae575b24266e11ea4c132b31 OK
2022/01/17 05:20:04 DEBUG : d: Making directory
2022/01/17 05:20:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:06 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:20:06 DEBUG : c/non empty space: Unchanged skipping
2022/01/17 05:20:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:09 DEBUG : a/potato2: md5 = 85c11e2bbf92158968a0747deda412ef OK
2022/01/17 05:20:09 INFO  : a/potato2: Copied (new)
2022/01/17 05:20:09 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': not deleting files as there were IO errors
2022/01/17 05:20:09 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': not deleting directories as there were IO errors
2022/01/17 05:20:13 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/01/17 05:20:14 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/01/17 05:20:15 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (16.84s)
=== RUN   TestSyncDeleteAfter
--- PASS: TestSyncDeleteAfter (0.00s)
=== RUN   TestSyncDeleteDuring
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:18 DEBUG : potato: md5 = 5c2b10daf8dd7d0054803fa92ae3ec7b OK
2022/01/17 05:20:20 DEBUG : empty space: md5 = b6d7644be829b6d6bd11a913d0a15e3a OK
2022/01/17 05:20:20 DEBUG : Waiting for deletions to finish
2022/01/17 05:20:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:20 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:20:20 DEBUG : empty space: Unchanged skipping
2022/01/17 05:20:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:21 INFO  : potato: Deleted
2022/01/17 05:20:22 DEBUG : potato2: md5 = 7d4d593ba970c9300ef50e0b22bbb5d0 OK
2022/01/17 05:20:22 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteDuring (7.77s)
=== RUN   TestSyncDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:25 DEBUG : potato: md5 = f79f974620521aaddf98c35c311218f0 OK
2022/01/17 05:20:27 DEBUG : empty space: md5 = 5436688ccb925bedd07e3c1d2c6416dc OK
2022/01/17 05:20:27 DEBUG : Waiting for deletions to finish
2022/01/17 05:20:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:28 INFO  : potato: Deleted
2022/01/17 05:20:28 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:20:28 DEBUG : empty space: Unchanged skipping
2022/01/17 05:20:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:30 DEBUG : potato2: md5 = 74a6b064f0af79cf9be7ccee43df13c2 OK
2022/01/17 05:20:30 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteBefore (8.55s)
=== RUN   TestCopyDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:34 DEBUG : potato: md5 = 9bc8e1d4263be5b52f9a0eb640d00424 OK
2022/01/17 05:20:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:36 DEBUG : potato2: md5 = 6694d5f482de38cdea9d0b70d3e926db OK
2022/01/17 05:20:36 INFO  : potato2: Copied (new)
--- PASS: TestCopyDeleteBefore (5.84s)
=== RUN   TestSyncWithExclude
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:40 DEBUG : potato2: md5 = bd01b80f5d67fe81a7e8b5bccf24d8e7 OK
2022/01/17 05:20:41 DEBUG : empty space: md5 = 81443517cacfff99e5dc9ff7af3c8346 OK
2022/01/17 05:20:42 DEBUG : enormous: Excluded
2022/01/17 05:20:42 DEBUG : potato2: Excluded
2022/01/17 05:20:42 DEBUG : potato2: Excluded from sync (and deletion)
2022/01/17 05:20:42 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:20:42 DEBUG : empty space: Unchanged skipping
2022/01/17 05:20:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:42 DEBUG : Waiting for deletions to finish
2022/01/17 05:20:42 INFO  : There was nothing to transfer
2022/01/17 05:20:42 DEBUG : enormous: Excluded
2022/01/17 05:20:42 DEBUG : potato2: Excluded
2022/01/17 05:20:43 DEBUG : potato2: Excluded from sync (and deletion)
2022/01/17 05:20:43 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2022/01/17 05:20:43 DEBUG : empty space: Unchanged skipping
2022/01/17 05:20:43 DEBUG : Local file system at /tmp/rclone107662796: Waiting for checks to finish
2022/01/17 05:20:43 DEBUG : Local file system at /tmp/rclone107662796: Waiting for transfers to finish
2022/01/17 05:20:43 DEBUG : Waiting for deletions to finish
2022/01/17 05:20:43 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExclude (6.10s)
=== RUN   TestSyncWithExcludeAndDeleteExcluded
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:46 DEBUG : potato2: md5 = 4854e1be9c8722104348dc030c48832d OK
2022/01/17 05:20:47 DEBUG : empty space: md5 = 050bf64e474e7fa63ec3315f8ecdc430 OK
2022/01/17 05:20:49 DEBUG : enormous: md5 = b593b2fa56b2a05845981cd59298e717 OK
2022/01/17 05:20:49 DEBUG : enormous: Excluded
2022/01/17 05:20:49 DEBUG : potato2: Excluded
2022/01/17 05:20:50 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:20:50 DEBUG : empty space: Unchanged skipping
2022/01/17 05:20:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:20:50 DEBUG : Waiting for deletions to finish
2022/01/17 05:20:50 INFO  : potato2: Deleted
2022/01/17 05:20:50 INFO  : enormous: Deleted
2022/01/17 05:20:50 INFO  : There was nothing to transfer
2022/01/17 05:20:51 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2022/01/17 05:20:51 DEBUG : empty space: Unchanged skipping
2022/01/17 05:20:51 DEBUG : Local file system at /tmp/rclone107662796: Waiting for checks to finish
2022/01/17 05:20:51 DEBUG : Local file system at /tmp/rclone107662796: Waiting for transfers to finish
2022/01/17 05:20:51 DEBUG : Waiting for deletions to finish
2022/01/17 05:20:51 INFO  : enormous: Deleted
2022/01/17 05:20:51 INFO  : potato2: Deleted
2022/01/17 05:20:51 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExcludeAndDeleteExcluded (7.72s)
=== RUN   TestSyncWithUpdateOlder
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:20:54 DEBUG : one: md5 = 013452f577405f86c22308e8d7bcdfef OK
2022/01/17 05:20:55 DEBUG : two: md5 = 75a2be8125d4ae4aaa1b6a9e81afb69f OK
2022/01/17 05:20:57 DEBUG : three: md5 = cab1eb53abf811c2d2b53f06dfcf329f OK
2022/01/17 05:20:58 DEBUG : four: md5 = a48f75dfba7bbee1e0f8e06f6af9fc3e OK
2022/01/17 05:20:59 DEBUG : four: Sizes differ (src 4 vs dst 8)
2022/01/17 05:20:59 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring
2022/01/17 05:20:59 DEBUG : one: Destination is newer than source, skipping
2022/01/17 05:20:59 DEBUG : three: Sizes identical
2022/01/17 05:20:59 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping
2022/01/17 05:20:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:20:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:00 DEBUG : two: md5 = 94d9d53f97421d0fc8a87bee2223eaa6 OK
2022/01/17 05:21:00 INFO  : two: Copied (replaced existing)
2022/01/17 05:21:00 DEBUG : four: md5 = 655233f7f1319ab8d69ab76226c6785f OK
2022/01/17 05:21:00 INFO  : four: Copied (replaced existing)
2022/01/17 05:21:00 DEBUG : five: md5 = 497f0ade7e5cd3e914f01ee160bc99d5 OK
2022/01/17 05:21:00 INFO  : five: Copied (new)
2022/01/17 05:21:00 DEBUG : Waiting for deletions to finish
    sync_test.go:992: Skip test with --checksum as no hashes supported
--- PASS: TestSyncWithUpdateOlder (12.49s)
=== 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-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
    sync_test.go:1058: Can track renames: false
2022/01/17 05:21:04 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Ignoring --track-renames as the source and destination do not have a common hash
2022/01/17 05:21:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:06 DEBUG : yam: md5 = 71f9fbb9579abe760ac1d9a01d10d682 OK
2022/01/17 05:21:06 INFO  : yam: Copied (new)
2022/01/17 05:21:07 DEBUG : potato: md5 = bf9beee740c19850f5f2957083b390df OK
2022/01/17 05:21:07 INFO  : potato: Copied (new)
2022/01/17 05:21:07 DEBUG : Waiting for deletions to finish
2022/01/17 05:21:07 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Ignoring --track-renames as the source and destination do not have a common hash
2022/01/17 05:21:07 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:21:07 DEBUG : potato: Unchanged skipping
2022/01/17 05:21:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:09 DEBUG : yaml: md5 = 9ddf36ed03d57ce5eab97fd10aca83e6 OK
2022/01/17 05:21:09 INFO  : yaml: Copied (new)
2022/01/17 05:21:09 DEBUG : Waiting for deletions to finish
2022/01/17 05:21:09 INFO  : yam: Deleted
--- PASS: TestSyncWithTrackRenames (7.05s)
=== RUN   TestParseRenamesStrategyModtime
--- PASS: TestParseRenamesStrategyModtime (0.00s)
=== RUN   TestRenamesStrategyModtime
--- PASS: TestRenamesStrategyModtime (0.00s)
=== RUN   TestSyncWithTrackRenamesStrategyModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
    sync_test.go:1127: Can track renames: true
2022/01/17 05:21:12 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Making map for --track-renames
2022/01/17 05:21:12 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Finished making map for --track-renames
2022/01/17 05:21:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for renames to finish
2022/01/17 05:21:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:13 DEBUG : yam: md5 = b173f99acafc4bed317c95f6d5bd66fd OK
2022/01/17 05:21:13 INFO  : yam: Copied (new)
2022/01/17 05:21:14 DEBUG : potato: md5 = 318aaa9070089697981be114b4e3fea5 OK
2022/01/17 05:21:14 INFO  : potato: Copied (new)
2022/01/17 05:21:14 DEBUG : Waiting for deletions to finish
2022/01/17 05:21:14 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:21:14 DEBUG : potato: Unchanged skipping
2022/01/17 05:21:14 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Making map for --track-renames
2022/01/17 05:21:14 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Finished making map for --track-renames
2022/01/17 05:21:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for renames to finish
2022/01/17 05:21:15 INFO  : yam: Moved (server-side) to: yaml
2022/01/17 05:21:15 INFO  : yaml: Renamed from "yam"
2022/01/17 05:21:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:15 DEBUG : Waiting for deletions to finish
2022/01/17 05:21:15 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyModtime (5.58s)
=== RUN   TestSyncWithTrackRenamesStrategyLeaf
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
    sync_test.go:1163: Can track renames: true
2022/01/17 05:21:17 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Making map for --track-renames
2022/01/17 05:21:17 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Finished making map for --track-renames
2022/01/17 05:21:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for renames to finish
2022/01/17 05:21:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:20 DEBUG : potato: md5 = 4df48f8c45270434c62557baaacc4907 OK
2022/01/17 05:21:20 INFO  : potato: Copied (new)
2022/01/17 05:21:20 DEBUG : sub/yam: md5 = 72b2bf70ac63ed23c16883d6683a0410 OK
2022/01/17 05:21:20 INFO  : sub/yam: Copied (new)
2022/01/17 05:21:20 DEBUG : Waiting for deletions to finish
2022/01/17 05:21:21 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:21:21 DEBUG : potato: Unchanged skipping
2022/01/17 05:21:21 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Making map for --track-renames
2022/01/17 05:21:21 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Finished making map for --track-renames
2022/01/17 05:21:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for renames to finish
2022/01/17 05:21:22 INFO  : sub/yam: Moved (server-side) to: yam
2022/01/17 05:21:22 INFO  : yam: Renamed from "sub/yam"
2022/01/17 05:21:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:22 DEBUG : Waiting for deletions to finish
2022/01/17 05:21:22 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyLeaf (8.40s)
=== RUN   TestMoveWithDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:21:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:28 DEBUG : sub dir/hello world: md5 = 7f9389743db6f7165a1cb4d01a5b2793 OK
2022/01/17 05:21:28 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:21:28 INFO  : sub dir/hello world: Deleted
2022/01/17 05:21:30 DEBUG : nested/sub dir/file: md5 = 7bbee60d57b2cc1d454b63e0ac531ac0 OK
2022/01/17 05:21:30 INFO  : nested/sub dir/file: Copied (new)
2022/01/17 05:21:30 INFO  : nested/sub dir/file: Deleted
2022/01/17 05:21:30 INFO  : sub dir: Removing directory
2022/01/17 05:21:30 INFO  : nested/sub dir: Removing directory
2022/01/17 05:21:30 INFO  : nested: Removing directory
2022/01/17 05:21:30 DEBUG : Local file system at /tmp/rclone107662796: deleted 3 directories
2022/01/17 05:21:34 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2022/01/17 05:21:34 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2022/01/17 05:21:36 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithDeleteEmptySrcDirs (11.10s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:21:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:40 DEBUG : sub dir/hello world: md5 = eff58c2bca28bea3b3d13bef90172faa OK
2022/01/17 05:21:40 INFO  : sub dir/hello world: Copied (new)
2022/01/17 05:21:40 INFO  : sub dir/hello world: Deleted
2022/01/17 05:21:42 DEBUG : nested/sub dir/file: md5 = 8e60e7a116a1e84a0522c125b54fcd23 OK
2022/01/17 05:21:42 INFO  : nested/sub dir/file: Copied (new)
2022/01/17 05:21:42 INFO  : nested/sub dir/file: Deleted
2022/01/17 05:21:45 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2022/01/17 05:21:46 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2022/01/17 05:21:47 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (10.85s)
=== RUN   TestMoveWithIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:21:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:49 DEBUG : existing: md5 = d53b6138fc940804f2cd811e973841fc OK
2022/01/17 05:21:49 INFO  : existing: Copied (new)
2022/01/17 05:21:49 INFO  : existing: Deleted
2022/01/17 05:21:50 DEBUG : existing-b: md5 = 5b94c172b616a5c115275a2fc21ad497 OK
2022/01/17 05:21:50 INFO  : existing-b: Copied (new)
2022/01/17 05:21:50 INFO  : existing-b: Deleted
2022/01/17 05:21:50 DEBUG : existing: Destination exists, skipping
2022/01/17 05:21:50 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set
2022/01/17 05:21:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:21:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:21:50 INFO  : There was nothing to transfer
--- PASS: TestMoveWithIgnoreExisting (4.86s)
=== RUN   TestServerSideMove
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:21:52 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7"
2022/01/17 05:21:52 DEBUG : Creating backend with remote "TestDrive:crypt/aci6jv0ipun16vjdmvjud8g0168eg7egh9bkcfbkoor54i4dm23dioonsu0k9736slhj4sj976t6e"
2022/01/17 05:21:55 DEBUG : potato2: md5 = a1bb58fad567dcd41dcb26616628dcc3 OK
2022/01/17 05:21:57 DEBUG : empty space: md5 = 11a0e813a7e9ffd87a7f1f7f3b7a7038 OK
2022/01/17 05:21:58 DEBUG : potato3: md5 = a5837e64dc8ed7f81d3066e201c671ff OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4' -> Encrypted drive 'TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7'
2022/01/17 05:22:01 DEBUG : empty space: md5 = 9de69dcce01be22da74f0891564f7bd0 OK
2022/01/17 05:22:03 DEBUG : potato3: md5 = 73d02f59ee4d5e6dbf2a2f60f062936b OK
2022/01/17 05:22:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7': Using server-side directory move
2022/01/17 05:22:03 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2022/01/17 05:22:03 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2022/01/17 05:22:03 DEBUG : empty space: Unchanged skipping
2022/01/17 05:22:03 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/01/17 05:22:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7': Waiting for checks to finish
2022/01/17 05:22:04 INFO  : empty space: Deleted
2022/01/17 05:22:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7': Waiting for transfers to finish
2022/01/17 05:22:04 INFO  : potato3: Deleted
2022/01/17 05:22:04 INFO  : potato2: Moved (server-side)
2022/01/17 05:22:05 INFO  : potato3: Moved (server-side)
2022/01/17 05:22:05 INFO  : There was nothing to transfer
2022/01/17 05:22:05 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-lujutiy4medajik6cemonig0"
2022/01/17 05:22:06 DEBUG : Creating backend with remote "TestDrive:crypt/7vedptcds9r8bvj2h1jvgh6betpq394n3e401eram76ha4hlgflecul09i8njk3uqrcgapvsbknva"
2022/01/17 05:22:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lujutiy4medajik6cemonig0': Using server-side directory move
2022/01/17 05:22:07 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-lujutiy4medajik6cemonig0': Server side directory move succeeded
2022/01/17 05:22:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lujutiy4medajik6cemonig0': Purge remote
2022/01/17 05:22:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ronojih7wugezix7texasiq7': Purge remote
2022/01/17 05:22:10 purge failed: directory not found
--- PASS: TestServerSideMove (17.73s)
=== RUN   TestServerSideMoveWithFilter
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:22:10 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vexehon2jujirof9rovopad2"
2022/01/17 05:22:10 DEBUG : Creating backend with remote "TestDrive:crypt/l0qgmlo722i8es7rcjjda784moap31r4ge48j9s4drfb5vajt2uhtqgjk4m4ju27ropj4th4crsku"
2022/01/17 05:22:13 DEBUG : potato2: md5 = 46b9f621c930f13d669190397ff27a9e OK
2022/01/17 05:22:15 DEBUG : empty space: md5 = 5e3f10c60301800f16b6ca7da87d5007 OK
2022/01/17 05:22:16 DEBUG : potato3: md5 = e33287e6eb3282ae13fb44d30a9b51a4 OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4' -> Encrypted drive 'TestCryptDrive:rclone-test-vexehon2jujirof9rovopad2'
2022/01/17 05:22:19 DEBUG : empty space: md5 = 3e1e1a2c2827984e67505699e22d455f OK
2022/01/17 05:22:21 DEBUG : potato3: md5 = 442c4a27d48b7aeed171e44b4bdf9893 OK
2022/01/17 05:22:21 DEBUG : empty space: Excluded from sync (and deletion)
2022/01/17 05:22:21 DEBUG : empty space: Excluded from sync (and deletion)
2022/01/17 05:22:21 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/01/17 05:22:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vexehon2jujirof9rovopad2': Waiting for checks to finish
2022/01/17 05:22:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vexehon2jujirof9rovopad2': Waiting for transfers to finish
2022/01/17 05:22:22 INFO  : potato3: Deleted
2022/01/17 05:22:22 INFO  : potato2: Moved (server-side)
2022/01/17 05:22:23 INFO  : potato3: Moved (server-side)
2022/01/17 05:22:23 INFO  : There was nothing to transfer
2022/01/17 05:22:23 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-liyomen5johojex1juminot8"
2022/01/17 05:22:23 DEBUG : Creating backend with remote "TestDrive:crypt/bnlcgu6318e2ak9usp3ck1mv4rlb0gfegmq3m1u3p8e7ksu1rgmoal20h6qglasljvb6m3d8jvpla"
2022/01/17 05:22:25 DEBUG : empty space: Excluded from sync (and deletion)
2022/01/17 05:22:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-liyomen5johojex1juminot8': Waiting for checks to finish
2022/01/17 05:22:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-liyomen5johojex1juminot8': Waiting for transfers to finish
2022/01/17 05:22:27 INFO  : potato2: Moved (server-side)
2022/01/17 05:22:27 INFO  : potato3: Moved (server-side)
2022/01/17 05:22:27 INFO  : There was nothing to transfer
2022/01/17 05:22:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-liyomen5johojex1juminot8': Purge remote
2022/01/17 05:22:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vexehon2jujirof9rovopad2': Purge remote
--- PASS: TestServerSideMoveWithFilter (20.25s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:22:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4"
2022/01/17 05:22:30 DEBUG : Creating backend with remote "TestDrive:crypt/0u5c1sd1hop189s906evk7d1l1c25khung7nqlljbocjeeqh9n65ntvalgekfa79813q6l9uchu8e"
2022/01/17 05:22:33 DEBUG : potato2: md5 = 2fc183b8bc1dd87ff6b73aad32a6e8f3 OK
2022/01/17 05:22:35 DEBUG : empty space: md5 = a73a3730a03c503543d02c63bde6af3d OK
2022/01/17 05:22:36 DEBUG : potato3: md5 = 10554f2b441f9e4dd8ee2ea2db539edd OK
2022/01/17 05:22:36 DEBUG : tomatoDir: Making directory
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4' -> Encrypted drive 'TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4'
2022/01/17 05:22:41 DEBUG : empty space: md5 = 3d2a57db0377e5a3512fd354e12e95cf OK
2022/01/17 05:22:42 DEBUG : potato3: md5 = b728da4facc7b8bbf0e7c93c0cf6978d OK
2022/01/17 05:22:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4': Using server-side directory move
2022/01/17 05:22:43 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2022/01/17 05:22:43 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2022/01/17 05:22:43 DEBUG : empty space: Unchanged skipping
2022/01/17 05:22:43 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/01/17 05:22:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4': Waiting for checks to finish
2022/01/17 05:22:44 INFO  : empty space: Deleted
2022/01/17 05:22:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4': Waiting for transfers to finish
2022/01/17 05:22:44 INFO  : potato3: Deleted
2022/01/17 05:22:44 INFO  : potato2: Moved (server-side)
2022/01/17 05:22:45 INFO  : potato3: Moved (server-side)
2022/01/17 05:22:45 INFO  : tomatoDir: Removing directory
2022/01/17 05:22:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': deleted 1 directories
2022/01/17 05:22:46 INFO  : There was nothing to transfer
2022/01/17 05:22:46 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-dipifok4haratir5curokeg0"
2022/01/17 05:22:46 DEBUG : Creating backend with remote "TestDrive:crypt/8fdit5p050j8383am5m3mc365ggf25dgq7edl12q42hvspaa763ur4almetqskjr0q8ve6hjuk2ng"
2022/01/17 05:22:48 DEBUG : tomatoDir: Making directory
2022/01/17 05:22:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dipifok4haratir5curokeg0': Using server-side directory move
2022/01/17 05:22:49 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-dipifok4haratir5curokeg0': Server side directory move succeeded
2022/01/17 05:22:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dipifok4haratir5curokeg0': Purge remote
2022/01/17 05:22:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-minezij4hoqozub7biwimuh4': Purge remote
2022/01/17 05:22:52 purge failed: directory not found
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (22.36s)
=== RUN   TestServerSideMoveOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
    sync_test.go:1399: Skipping test as remote supports DirMove
--- SKIP: TestServerSideMoveOverlap (0.57s)
=== RUN   TestSyncOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:22:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/rclone-sync-test"
2022/01/17 05:22:53 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0"
--- PASS: TestSyncOverlap (2.16s)
=== RUN   TestSyncCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:22:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:22:55 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:22:57 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/CompareDest"
2022/01/17 05:22:57 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/gveqi14airsml4bgu7krj116o8"
2022/01/17 05:22:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:22:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:02 DEBUG : one: md5 = 9bcd97249c8161bb893cf7773d5d7fed OK
2022/01/17 05:23:02 INFO  : one: Copied (new)
2022/01/17 05:23:02 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:03 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/01/17 05:23:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:05 DEBUG : one: md5 = c38033cc0a0683fd952e500f5d896dd9 OK
2022/01/17 05:23:05 INFO  : one: Copied (replaced existing)
2022/01/17 05:23:05 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:07 DEBUG : dst/one: md5 = 3326d5cd66718cb907e7a5ae2d9c9007 OK
2022/01/17 05:23:09 DEBUG : CompareDest/one: md5 = 84f489d33224bacbdf313c49376bf6c3 OK
2022/01/17 05:23:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:11 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:23:11 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/17 05:23:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:11 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:11 INFO  : There was nothing to transfer
2022/01/17 05:23:13 DEBUG : CompareDest/two: md5 = 2d0df3fdeb2e0c312824e02278c7bdae OK
2022/01/17 05:23:14 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:23:14 DEBUG : two: Destination found in --compare-dest, skipping
2022/01/17 05:23:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:15 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:23:15 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/17 05:23:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:15 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:15 INFO  : There was nothing to transfer
2022/01/17 05:23:16 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:23:16 DEBUG : two: Destination found in --compare-dest, skipping
2022/01/17 05:23:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:16 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:23:16 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/17 05:23:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:16 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:16 INFO  : There was nothing to transfer
    sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test
2022/01/17 05:23:18 DEBUG : two: Sizes differ (src 5 vs dst 3)
2022/01/17 05:23:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:18 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:23:18 DEBUG : one: Destination found in --compare-dest, skipping
2022/01/17 05:23:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:19 DEBUG : two: md5 = 968bf49b5fa9e2ba4cecf3131075c95c OK
2022/01/17 05:23:19 INFO  : two: Copied (new)
2022/01/17 05:23:19 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:23:24 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:23:24 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:23:24 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncCompareDest (29.99s)
=== RUN   TestSyncMultipleCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:23:28 DEBUG : pre-dest1/1: md5 = a0e1f20ffd5935b9b06073d490049979 OK
2022/01/17 05:23:31 DEBUG : pre-dest2/2: md5 = 8baa845089eb1ad7d88926ca6bfe7170 OK
2022/01/17 05:23:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dest"
2022/01/17 05:23:31 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/rg03c1jvnehrrc617i0lnqjddc"
2022/01/17 05:23:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/pre-dest1"
2022/01/17 05:23:33 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/bbnblvh6k061ssopqrp18kd7gc"
2022/01/17 05:23:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/pre-dest2"
2022/01/17 05:23:34 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/dgicm1h6b5ejvlltm8eeif0bnk"
2022/01/17 05:23:35 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:23:35 DEBUG : 1: Destination found in --compare-dest, skipping
2022/01/17 05:23:36 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:23:36 DEBUG : 2: Destination found in --compare-dest, skipping
2022/01/17 05:23:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dest': Waiting for checks to finish
2022/01/17 05:23:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dest': Waiting for transfers to finish
2022/01/17 05:23:39 DEBUG : 3: md5 = eaa87718031d000da0ebb72ded95e86f OK
2022/01/17 05:23:39 INFO  : 3: Copied (new)
2022/01/17 05:23:39 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:43 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc"
2022/01/17 05:23:44 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro"
2022/01/17 05:23:45 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg"
--- PASS: TestSyncMultipleCompareDest (20.12s)
=== RUN   TestSyncCopyDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:23:45 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:23:46 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:23:47 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/CopyDest"
2022/01/17 05:23:47 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/d09o6po3f7bm6ce32vdgs8h9ls"
2022/01/17 05:23:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:52 DEBUG : one: md5 = cfe5a29cd9a7529d78d39ced38235067 OK
2022/01/17 05:23:52 INFO  : one: Copied (new)
2022/01/17 05:23:52 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:23:54 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/01/17 05:23:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:23:55 DEBUG : one: md5 = c712eabdd5fc77f6b100decc1190a787 OK
2022/01/17 05:23:55 INFO  : one: Copied (replaced existing)
2022/01/17 05:23:55 DEBUG : Waiting for deletions to finish
2022/01/17 05:23:57 DEBUG : dst/one: md5 = 4ce12a7b04d1dfddee82d590041e0c61 OK
2022/01/17 05:24:00 DEBUG : CopyDest/one: md5 = bc83e57ed703b8a5a212fe4cf86bdeb8 OK
2022/01/17 05:24:00 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/BackupDir"
2022/01/17 05:24:00 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/s6dbk3lfi7c9kfvo6j7bla9m0g"
2022/01/17 05:24:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:24:03 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:03 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/01/17 05:24: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/17 05:24:04 DEBUG : pacer: Rate limited, increasing sleep to 1.944858823s
2022/01/17 05:24:04 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/17 05:24:04 DEBUG : pacer: Rate limited, increasing sleep to 2.81852306s
2022/01/17 05:24:07 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:24:07 INFO  : one: Moved (server-side)
2022/01/17 05:24:08 INFO  : one: Copied (server-side copy)
2022/01/17 05:24:08 DEBUG : one: Destination found in --copy-dest, using server-side copy
2022/01/17 05:24:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:24:08 DEBUG : Waiting for deletions to finish
2022/01/17 05:24:11 DEBUG : CopyDest/two: md5 = ea450de3cba167b8fb95025893a884da OK
2022/01/17 05:24:12 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:13 INFO  : two: Copied (server-side copy)
2022/01/17 05:24:13 DEBUG : two: Destination found in --copy-dest, using server-side copy
2022/01/17 05:24:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:24:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:13 DEBUG : one: Unchanged skipping
2022/01/17 05:24:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:24:13 DEBUG : Waiting for deletions to finish
2022/01/17 05:24:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:24:15 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:15 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:15 DEBUG : two: Unchanged skipping
2022/01/17 05:24:15 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:15 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:15 DEBUG : one: Unchanged skipping
2022/01/17 05:24:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:24:15 DEBUG : Waiting for deletions to finish
2022/01/17 05:24:15 INFO  : There was nothing to transfer
2022/01/17 05:24:17 DEBUG : CopyDest/three: md5 = ec605c3b539bc2864e6cdb9bb8722fd4 OK
2022/01/17 05:24:18 DEBUG : three: Sizes differ (src 7 vs dst 5)
2022/01/17 05:24:18 DEBUG : three: Destination not found in --copy-dest
2022/01/17 05:24:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:24:19 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:19 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:19 DEBUG : two: Unchanged skipping
2022/01/17 05:24:19 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:19 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/01/17 05:24:19 DEBUG : one: Unchanged skipping
2022/01/17 05:24:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:24:20 DEBUG : three: md5 = b27da12a37ec327a1b7a81e60ad3d50f OK
2022/01/17 05:24:20 INFO  : three: Copied (new)
2022/01/17 05:24:20 DEBUG : Waiting for deletions to finish
2022/01/17 05:24:23 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/17 05:24:23 DEBUG : pacer: Rate limited, increasing sleep to 1.568058946s
2022/01/17 05:24:23 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:24:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2022/01/17 05:24:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:24:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:24:28 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2022/01/17 05:24:28 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:24:28 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:24:29 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
--- PASS: TestSyncCopyDest (43.98s)
=== RUN   TestSyncBackupDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:24:32 DEBUG : dst/one: md5 = bd44f78fb38c5ff58f852453fca8a3c5 OK
2022/01/17 05:24:34 DEBUG : dst/two: md5 = 6bc18f4718f3fc692934366de0790ace OK
2022/01/17 05:24:35 DEBUG : dst/three.txt: md5 = d7c15d19f0fe1baf59232fa416787a56 OK
2022/01/17 05:24:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:24:36 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:24:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/backup"
2022/01/17 05:24:37 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/1nrff024r7pq65ecp72fc28jb0"
2022/01/17 05:24:39 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/17 05:24:39 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:24:39 DEBUG : two: Unchanged skipping
2022/01/17 05:24:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:24:40 INFO  : one: Moved (server-side)
2022/01/17 05:24:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:24:42 DEBUG : one: md5 = 530b4b1974b35558fe86408c70c16153 OK
2022/01/17 05:24:42 INFO  : one: Copied (new)
2022/01/17 05:24:42 DEBUG : Waiting for deletions to finish
2022/01/17 05:24:43 INFO  : three.txt: Moved (server-side)
2022/01/17 05:24:43 INFO  : three.txt: Moved into backup dir
2022/01/17 05:24:45 DEBUG : dst/three.txt: md5 = fadb7a7c48d56d487d5351a25898d08c OK
2022/01/17 05:24:46 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/17 05:24:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:24:46 DEBUG : two: Unchanged skipping
2022/01/17 05:24:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:24:46 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/17 05:24:46 DEBUG : pacer: Rate limited, increasing sleep to 1.848484529s
2022/01/17 05:24:47 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:24:47 INFO  : one: Deleted
2022/01/17 05:24:49 INFO  : one: Moved (server-side)
2022/01/17 05:24:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:24:51 DEBUG : one: md5 = e4ed2579305b643eb2bae997755b4e01 OK
2022/01/17 05:24:51 INFO  : one: Copied (new)
2022/01/17 05:24:51 DEBUG : Waiting for deletions to finish
2022/01/17 05:24:51 INFO  : three.txt: Deleted
2022/01/17 05:24:52 INFO  : three.txt: Moved (server-side)
2022/01/17 05:24:52 INFO  : three.txt: Moved into backup dir
2022/01/17 05:24:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:24:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:24:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:24:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/17 05:24:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/17 05:24:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
--- PASS: TestSyncBackupDir (28.40s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:25:00 DEBUG : dst/one: md5 = 64335bc85e78afa5f95a61e813e8a720 OK
2022/01/17 05:25:02 DEBUG : dst/two: md5 = f7ceaa3b0bbfa0dcbd0a12a14e11ab11 OK
2022/01/17 05:25:04 DEBUG : dst/three.txt: md5 = 8c91701534b26a702565376dd1bfc725 OK
2022/01/17 05:25:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:25:04 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:25:06 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/backup"
2022/01/17 05:25:06 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/1nrff024r7pq65ecp72fc28jb0"
2022/01/17 05:25:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:25:08 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/17 05:25:08 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:25:08 DEBUG : two: Unchanged skipping
2022/01/17 05:25:10 INFO  : one: Moved (server-side) to: one.bak
2022/01/17 05:25:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:25:11 DEBUG : one: md5 = d7abcb426636871299e87ada42daf0f6 OK
2022/01/17 05:25:11 INFO  : one: Copied (new)
2022/01/17 05:25:11 DEBUG : Waiting for deletions to finish
2022/01/17 05:25:13 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/17 05:25:13 INFO  : three.txt: Moved into backup dir
2022/01/17 05:25:15 DEBUG : dst/three.txt: md5 = 112c882f049bcb00a4a7daf4c7a67b14 OK
2022/01/17 05:25:16 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/17 05:25:16 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:25:16 DEBUG : two: Unchanged skipping
2022/01/17 05:25:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:25:17 INFO  : one.bak: Deleted
2022/01/17 05:25:18 INFO  : one: Moved (server-side) to: one.bak
2022/01/17 05:25:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:25:19 DEBUG : one: md5 = 0d77da77ceaf9b734e6be8e0141aacee OK
2022/01/17 05:25:19 INFO  : one: Copied (new)
2022/01/17 05:25:19 DEBUG : Waiting for deletions to finish
2022/01/17 05:25:20 INFO  : three.txt.bak: Deleted
2022/01/17 05:25:21 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/17 05:25:21 INFO  : three.txt: Moved into backup dir
2022/01/17 05:25:25 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:25:25 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:25:26 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/17 05:25:26 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/17 05:25:26 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/17 05:25:26 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
--- PASS: TestSyncBackupDirWithSuffix (28.86s)
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:25:29 DEBUG : dst/one: md5 = 19c7277d66af22223a90ca60471cfd0e OK
2022/01/17 05:25:31 DEBUG : dst/two: md5 = 4b1059f5be8120bf1b1c08c9c844a0ab OK
2022/01/17 05:25:33 DEBUG : dst/three.txt: md5 = ba6dd7d9e5a9d2a9472a5ce8728c32d3 OK
2022/01/17 05:25:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:25:33 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:25:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/backup"
2022/01/17 05:25:34 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/1nrff024r7pq65ecp72fc28jb0"
2022/01/17 05:25:36 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/17 05:25:36 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:25:36 DEBUG : two: Unchanged skipping
2022/01/17 05:25:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:25:38 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/17 05:25:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:25:40 DEBUG : one: md5 = dd592083b14204666b59785130365e33 OK
2022/01/17 05:25:40 INFO  : one: Copied (new)
2022/01/17 05:25:40 DEBUG : Waiting for deletions to finish
2022/01/17 05:25:41 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/17 05:25:41 INFO  : three.txt: Moved into backup dir
2022/01/17 05:25:43 DEBUG : dst/three.txt: md5 = 2a6bbf74a41ed2c39c49cae5e77a8dec OK
2022/01/17 05:25:44 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/17 05:25:44 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:25:44 DEBUG : two: Unchanged skipping
2022/01/17 05:25:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:25:45 INFO  : one-2019-01-01: Deleted
2022/01/17 05:25:46 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/17 05:25:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:25:47 DEBUG : one: md5 = 39a9834bcecfe6c7b2c6c25a2a0e078c OK
2022/01/17 05:25:47 INFO  : one: Copied (new)
2022/01/17 05:25:47 DEBUG : Waiting for deletions to finish
2022/01/17 05:25:48 INFO  : three-2019-01-01.txt: Deleted
2022/01/17 05:25:49 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/17 05:25:49 INFO  : three.txt: Moved into backup dir
2022/01/17 05:25:50 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/17 05:25:50 DEBUG : pacer: Rate limited, increasing sleep to 1.796084294s
2022/01/17 05:25:50 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/01/17 05:25:50 DEBUG : pacer: Rate limited, increasing sleep to 2.05213807s
2022/01/17 05:25:53 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:25:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:25:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:25:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/17 05:25:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/01/17 05:25:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/01/17 05:25:57 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (31.31s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:26:00 DEBUG : dst/one: md5 = 97a677e9dbd41c67d49535a1bc33c9a0 OK
2022/01/17 05:26:02 DEBUG : dst/two: md5 = 932309dc226e23684113ccc028a8058a OK
2022/01/17 05:26:04 DEBUG : dst/three.txt: md5 = 28b15fe5b5da1c8069b061e0ef289d62 OK
2022/01/17 05:26:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:26:04 DEBUG : Config file has changed externaly - reloading
2022/01/17 05:26:04 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:26:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:26:06 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/17 05:26:06 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:26:06 DEBUG : two: Unchanged skipping
2022/01/17 05:26:07 INFO  : one: Moved (server-side) to: one.bak
2022/01/17 05:26:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:26:08 DEBUG : one: md5 = a6bba4769a98429e1300d5c932d80b13 OK
2022/01/17 05:26:08 INFO  : one: Copied (new)
2022/01/17 05:26:08 DEBUG : Waiting for deletions to finish
2022/01/17 05:26:09 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/17 05:26:09 INFO  : three.txt: Moved into backup dir
2022/01/17 05:26:11 DEBUG : dst/three.txt: md5 = bb95b7a1f1ae2f4f0125dc5fafa5a5de OK
2022/01/17 05:26:12 DEBUG : three.txt.bak: Excluded from sync (and deletion)
2022/01/17 05:26:12 DEBUG : one.bak: Excluded from sync (and deletion)
2022/01/17 05:26:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for checks to finish
2022/01/17 05:26:12 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/17 05:26:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:26:12 DEBUG : two: Unchanged skipping
2022/01/17 05:26:13 INFO  : one.bak: Deleted
2022/01/17 05:26:14 INFO  : one: Moved (server-side) to: one.bak
2022/01/17 05:26:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst': Waiting for transfers to finish
2022/01/17 05:26:15 DEBUG : one: md5 = cf2b71b664dcfc10c8f88a16262270dc OK
2022/01/17 05:26:15 INFO  : one: Copied (new)
2022/01/17 05:26:15 DEBUG : Waiting for deletions to finish
2022/01/17 05:26:16 INFO  : three.txt.bak: Deleted
2022/01/17 05:26:17 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/17 05:26:17 INFO  : three.txt: Moved into backup dir
2022/01/17 05:26:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:26:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/17 05:26:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/17 05:26:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/17 05:26:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/17 05:26:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncBackupDirSuffixOnly (23.94s)
=== RUN   TestSyncSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:26:25 DEBUG : dst/one: md5 = 98d2981fc72e5995e3ad6fdd3d35c759 OK
2022/01/17 05:26:26 DEBUG : dst/two: md5 = 9faf12a8d9b09af828a841efabc4483e OK
2022/01/17 05:26:28 DEBUG : dst/three.txt: md5 = ae457e9a77eccc2408bf03dac7997024 OK
2022/01/17 05:26:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:26:28 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:26:30 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/17 05:26:31 INFO  : one: Moved (server-side) to: one.bak
2022/01/17 05:26:32 DEBUG : one: md5 = 76b0466728ede785007533f263a97b51 OK
2022/01/17 05:26:32 INFO  : one: Copied (new)
2022/01/17 05:26:32 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:26:32 DEBUG : two: Unchanged skipping
2022/01/17 05:26:33 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2022/01/17 05:26:34 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/17 05:26:35 DEBUG : three.txt: md5 = e0e779e72c69c625301590e54c40c241 OK
2022/01/17 05:26:35 INFO  : three.txt: Copied (new)
2022/01/17 05:26:37 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/17 05:26:38 INFO  : one.bak: Deleted
2022/01/17 05:26:38 INFO  : one: Moved (server-side) to: one.bak
2022/01/17 05:26:40 DEBUG : one: md5 = 32282d85894edf4b0abbc361ab4565a6 OK
2022/01/17 05:26:40 INFO  : one: Copied (new)
2022/01/17 05:26:40 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:26:40 DEBUG : two: Unchanged skipping
2022/01/17 05:26:40 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2022/01/17 05:26:41 INFO  : three.txt.bak: Deleted
2022/01/17 05:26:42 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/01/17 05:26:44 DEBUG : three.txt: md5 = efc67686276e14b33311f94e14695ade OK
2022/01/17 05:26:44 INFO  : three.txt: Copied (new)
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/01/17 05:26:48 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
--- PASS: TestSyncSuffix (27.28s)
=== RUN   TestSyncSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:26:52 DEBUG : dst/one: md5 = a90adab9b41bbd0a63ebd98424522a9d OK
2022/01/17 05:26:53 DEBUG : dst/two: md5 = 5c4a7606970f52a7e891707375cf2ba3 OK
2022/01/17 05:26:55 DEBUG : dst/three.txt: md5 = 2dcef0b86f93efe91d4421dd44eeab65 OK
2022/01/17 05:26:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4/dst"
2022/01/17 05:26:55 DEBUG : Creating backend with remote "TestDrive:crypt/26fk90ui0pmeapks7s3laka6kgg9iooapn0gmb434v8g86bjhsdgm47rm4n42shoca9973knoi8vm/31u3jie661vd5p8j7rtc3hgbh0"
2022/01/17 05:26:57 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/01/17 05:26:58 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/17 05:26:59 DEBUG : one: md5 = 446ae4680881d81e498fbfe9954b9332 OK
2022/01/17 05:26:59 INFO  : one: Copied (new)
2022/01/17 05:27:00 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:27:00 DEBUG : two: Unchanged skipping
2022/01/17 05:27:00 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2022/01/17 05:27:01 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/17 05:27:02 DEBUG : three.txt: md5 = c08f9aa639a07178de7d2210a08169c7 OK
2022/01/17 05:27:02 INFO  : three.txt: Copied (new)
2022/01/17 05:27:04 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/01/17 05:27:05 INFO  : one-2019-01-01: Deleted
2022/01/17 05:27:05 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/01/17 05:27:07 DEBUG : one: md5 = d27b1c138f53b1fd212b3596399ddf8a OK
2022/01/17 05:27:07 INFO  : one: Copied (new)
2022/01/17 05:27:07 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:27:07 DEBUG : two: Unchanged skipping
2022/01/17 05:27:08 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2022/01/17 05:27:09 INFO  : three-2019-01-01.txt: Deleted
2022/01/17 05:27:09 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/01/17 05:27:11 DEBUG : three.txt: md5 = 57a7b4cba6acd0cb3228c8ec79be9d0e OK
2022/01/17 05:27:11 INFO  : three.txt: Copied (new)
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/01/17 05:27:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
--- PASS: TestSyncSuffixKeepExtension (27.39s)
=== RUN   TestSyncUTFNorm
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:27:18 DEBUG : Testêé: md5 = 4171fde673da2ef1a03f3182bb2c0f73 OK
2022/01/17 05:27:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:27:19 DEBUG : Testêé: Sizes differ (src 14 vs dst 18)
2022/01/17 05:27:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:27:20 DEBUG : Testêé: md5 = 0fc9e840945e7d91e1e1df968490a8b4 OK
2022/01/17 05:27:20 INFO  : Testêé: Copied (replaced existing)
2022/01/17 05:27:20 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncUTFNorm (4.81s)
=== RUN   TestSyncImmutable
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:27:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:27:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:27:24 DEBUG : existing: md5 = aa8d8a608545160d0968b95312e0c1c8 OK
2022/01/17 05:27:24 INFO  : existing: Copied (new)
2022/01/17 05:27:24 DEBUG : Waiting for deletions to finish
2022/01/17 05:27:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:27:25 DEBUG : existing: Sizes differ (src 8 vs dst 6)
2022/01/17 05:27:25 ERROR : existing: Source and destination exist but do not match: immutable file modified
2022/01/17 05:27:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:27:25 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': not deleting files as there were IO errors
2022/01/17 05:27:25 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': not deleting directories as there were IO errors
--- PASS: TestSyncImmutable (5.25s)
=== RUN   TestSyncIgnoreCase
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:27:28 DEBUG : EXISTING: md5 = 86d84ffaef77094b31346ed011d77a9c OK
2022/01/17 05:27:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:27:29 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:27:29 DEBUG : existing: Unchanged skipping
2022/01/17 05:27:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:27:29 DEBUG : Waiting for deletions to finish
2022/01/17 05:27:29 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreCase (3.73s)
=== RUN   TestMaxTransfer
=== RUN   TestMaxTransfer/Hard
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", 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-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", 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-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
    sync_test.go:1989: This test only runs on local
--- PASS: TestMaxTransfer (1.58s)
    --- SKIP: TestMaxTransfer/Hard (0.56s)
    --- SKIP: TestMaxTransfer/Soft (0.51s)
    --- SKIP: TestMaxTransfer/Cautious (0.51s)
=== RUN   TestSyncConcurrentDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:27:34 DEBUG : both0: md5 = a8da153de820bfd9d9f0ebb92255a116 OK
2022/01/17 05:27:35 DEBUG : only0: md5 = b0c167364d804bffc4932973cd548a5e OK
2022/01/17 05:27:37 DEBUG : both1: md5 = f798efc02b3e3e8d8819542c120cbced OK
2022/01/17 05:27:38 DEBUG : only1: md5 = 08008e48ed8d586ded2b14fea2ad0971 OK
2022/01/17 05:27:40 DEBUG : both2: md5 = 17d7002e6bbbea057bec4f5119abf9aa OK
2022/01/17 05:27:41 DEBUG : only2: md5 = 48f2517264930de41d4596fc80dc045d OK
2022/01/17 05:27:43 DEBUG : both3: md5 = 222c92d70348097f1e92bf87456488e4 OK
2022/01/17 05:27:44 DEBUG : only3: md5 = 962e38f7b6ffa5f441c5a7f4a35083aa OK
2022/01/17 05:27:46 DEBUG : both4: md5 = 0ae4fd8f1164e84c7c584020f30b5038 OK
2022/01/17 05:27:48 DEBUG : only4: md5 = a737ee74617f891a9a4f33086917981e OK
2022/01/17 05:27:49 DEBUG : both5: md5 = a8c6567d45b4bc68c16455a313386df5 OK
2022/01/17 05:27:51 DEBUG : only5: md5 = 13006c0fba7887cb14e45f6afa9198c8 OK
2022/01/17 05:27:52 DEBUG : both6: md5 = 31f24aaca8755437ecabf274577515d2 OK
2022/01/17 05:27:54 DEBUG : only6: md5 = ce4586aaebed3a161e7943e0c6838d2b OK
2022/01/17 05:27:56 DEBUG : both7: md5 = 04fb83290ac7e285a2833a172dd7e8e4 OK
2022/01/17 05:27:57 DEBUG : only7: md5 = c68b6ac983fdb7fa78be338e58ce431f OK
2022/01/17 05:27:59 DEBUG : both8: md5 = e1d5a751d94314980b3895d2ab2cb938 OK
2022/01/17 05:28:01 DEBUG : only8: md5 = 6ff9806009ca38e161140fed4a486d8f OK
2022/01/17 05:28:02 DEBUG : both9: md5 = ba094940b51a6a41e3f4c41b72f4e7bd OK
2022/01/17 05:28:04 DEBUG : only9: md5 = 59c1bac8f8ec39ee13e3129f0a2e6a89 OK
2022/01/17 05:28:06 DEBUG : both10: md5 = 564358574665e772470b4e64574ecad1 OK
2022/01/17 05:28:07 DEBUG : only10: md5 = abc09fdae78b044595fd75e26c9a7fa3 OK
2022/01/17 05:28:09 DEBUG : both11: md5 = e5dd02e2a75e890933c7ac7cd54359ba OK
2022/01/17 05:28:10 DEBUG : only11: md5 = 0205accaef5246d31372a30fe385f9d6 OK
2022/01/17 05:28:12 DEBUG : both12: md5 = d5cd73428e63b769221045b042a06e1f OK
2022/01/17 05:28:14 DEBUG : only12: md5 = d6cf8e15b50642f2ab2c1fe61cf40576 OK
2022/01/17 05:28:15 DEBUG : both13: md5 = 37558e8c937ba651df6b100b9ac25e6e OK
2022/01/17 05:28:17 DEBUG : only13: md5 = 11c6e6926488ced09593251ab1b18d2f OK
2022/01/17 05:28:19 DEBUG : both14: md5 = 210059f956038be0094b0cc6115c1cd3 OK
2022/01/17 05:28:21 DEBUG : only14: md5 = fc66959842892d11d3ebd9edee589338 OK
2022/01/17 05:28:22 DEBUG : both15: md5 = 0bcccbc8b7fbff98bb5bb2f6d80d15a1 OK
2022/01/17 05:28:24 DEBUG : only15: md5 = ff7bcf6dddab2891c2c211e9a21a8ef1 OK
2022/01/17 05:28:26 DEBUG : both16: md5 = 9832d0f98bfff1d9c73a8a6e4a719e55 OK
2022/01/17 05:28:27 DEBUG : only16: md5 = 6702dd5996e0093eb4c1e485d949376c OK
2022/01/17 05:28:29 DEBUG : both17: md5 = fb534f1ee3b2848abc94dd263343a12a OK
2022/01/17 05:28:31 DEBUG : only17: md5 = 2eb790c5eb49b37c2baa1bcca8b86f5a OK
2022/01/17 05:28:32 DEBUG : both18: md5 = 078612ac8862f31f8088dcbb1233cfdd OK
2022/01/17 05:28:34 DEBUG : only18: md5 = 2bff0dc8998b6dc028e2726854ba7985 OK
2022/01/17 05:28:35 DEBUG : both19: md5 = 68642072c9538095bfacd904bcc5225d OK
2022/01/17 05:28:37 DEBUG : only19: md5 = 1d1621eba2d1d2d60d308bb6d5fd8255 OK
2022/01/17 05:28:38 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both0: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both1: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both12: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both11: Unchanged skipping
2022/01/17 05:28:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:28:38 DEBUG : both13: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both10: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both17: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both18: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both19: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both2: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both3: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both4: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both5: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both6: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both7: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both8: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both9: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:28:38 DEBUG : both15: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both16: Unchanged skipping
2022/01/17 05:28:38 DEBUG : both14: Unchanged skipping
2022/01/17 05:28:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:28:38 DEBUG : Waiting for deletions to finish
2022/01/17 05:28:39 INFO  : only18: Deleted
2022/01/17 05:28:39 INFO  : only1: Deleted
2022/01/17 05:28:39 INFO  : only19: Deleted
2022/01/17 05:28:39 INFO  : only0: Deleted
2022/01/17 05:28:39 INFO  : only12: Deleted
2022/01/17 05:28:39 INFO  : only3: Deleted
2022/01/17 05:28:39 INFO  : only13: Deleted
2022/01/17 05:28:39 INFO  : only17: Deleted
2022/01/17 05:28:40 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/17 05:28:40 DEBUG : pacer: Rate limited, increasing sleep to 1.338758197s
2022/01/17 05:28:40 DEBUG : pacer: Reducing sleep to 0s
2022/01/17 05:28:40 INFO  : only10: Deleted
2022/01/17 05:28:40 INFO  : only11: Deleted
2022/01/17 05:28:40 INFO  : only14: Deleted
2022/01/17 05:28:40 INFO  : only16: Deleted
2022/01/17 05:28:41 INFO  : only8: Deleted
2022/01/17 05:28:42 INFO  : only15: Deleted
2022/01/17 05:28:42 INFO  : only2: Deleted
2022/01/17 05:28:42 INFO  : only6: Deleted
2022/01/17 05:28:42 INFO  : only4: Deleted
2022/01/17 05:28:42 INFO  : only5: Deleted
2022/01/17 05:28:42 INFO  : only7: Deleted
2022/01/17 05:28:42 INFO  : only9: Deleted
2022/01/17 05:28:42 INFO  : There was nothing to transfer
--- PASS: TestSyncConcurrentDelete (83.63s)
=== RUN   TestSyncConcurrentTruncate
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4'", Local "Local file system at /tmp/rclone107662796", Modify Window "1ms"
2022/01/17 05:28:57 DEBUG : both0: md5 = 085551ee593940bd313d173878f806b9 OK
2022/01/17 05:28:59 DEBUG : only0: md5 = 612c297bc73b1477143f15f553f37392 OK
2022/01/17 05:29:00 DEBUG : both1: md5 = 3913aba546c334729df7a6665bed6d40 OK
2022/01/17 05:29:02 DEBUG : only1: md5 = 1f3c0fbe1561bf4aaa9f5e5a2526a04f OK
2022/01/17 05:29:04 DEBUG : both2: md5 = cf371c7c9d168cbf3d6d89f82b3a12ab OK
2022/01/17 05:29:06 DEBUG : only2: md5 = acc5dbcd943a55bdb58171e0bea2e23d OK
2022/01/17 05:29:07 DEBUG : both3: md5 = e1f9f5f0c913c91eb7648750a74d0e0b OK
2022/01/17 05:29:09 DEBUG : only3: md5 = 643613a7fd4b4a0fc657b0dac33661ab OK
2022/01/17 05:29:10 DEBUG : both4: md5 = 693830007bde32c48cc9832bcdc798e9 OK
2022/01/17 05:29:12 DEBUG : only4: md5 = 5388799a63709c9f44e99d76df573562 OK
2022/01/17 05:29:14 DEBUG : both5: md5 = eb7e5b1bb57f2e51ff2879c8b06d6443 OK
2022/01/17 05:29:15 DEBUG : only5: md5 = 573b9b25270ae39c234d14a7f576584e OK
2022/01/17 05:29:17 DEBUG : both6: md5 = f398f2d47dd16f45f5b003c54e9edfec OK
2022/01/17 05:29:19 DEBUG : only6: md5 = e1e1f1b648800dfe1e7fcb2d2f2f9b4b OK
2022/01/17 05:29:20 DEBUG : both7: md5 = 8dfc566bf8f4c72324d138ac4707d381 OK
2022/01/17 05:29:22 DEBUG : only7: md5 = 5ee861ca42dd2f2678006562037edd16 OK
2022/01/17 05:29:23 DEBUG : both8: md5 = f159cdf9879de87e4ca95f86c768c363 OK
2022/01/17 05:29:26 DEBUG : only8: md5 = 043e3b3a6d29f29d4d5e29dd4557f0d1 OK
2022/01/17 05:29:27 DEBUG : both9: md5 = 5d949166e4d278a681d6e055019cd72c OK
2022/01/17 05:29:29 DEBUG : only9: md5 = 1c3258ba630c6b0e6c17d6bf2e57b148 OK
2022/01/17 05:29:30 DEBUG : both10: md5 = e8727adcf66c026c5e6f5deb81c8a619 OK
2022/01/17 05:29:32 DEBUG : only10: md5 = cf94d5de836a70434ff5152cef1d63e1 OK
2022/01/17 05:29:34 DEBUG : both11: md5 = e8789e1540f0ca821d4518c18c69360a OK
2022/01/17 05:29:35 DEBUG : only11: md5 = 88e4a86da14f5d5ce388b6fe3557368b OK
2022/01/17 05:29:37 DEBUG : both12: md5 = c9ebae78f95e845de58e1e9e17d863d8 OK
2022/01/17 05:29:39 DEBUG : only12: md5 = 0768ece01ef1b736a85fc5728ed7e6f4 OK
2022/01/17 05:29:40 DEBUG : both13: md5 = 1a8e18be52ef7bc21e9fcb4b731af28c OK
2022/01/17 05:29:42 DEBUG : only13: md5 = 60c3534da99ba2895cdeacd3c67be502 OK
2022/01/17 05:29:44 DEBUG : both14: md5 = 4f55bd46a6bdd7035bac2d234ffd9d10 OK
2022/01/17 05:29:45 DEBUG : only14: md5 = 3b5db854e63b7793f4322b02f4622a9f OK
2022/01/17 05:29:47 DEBUG : both15: md5 = 5c1072d0ed8abda14db580c4c5e7f5b4 OK
2022/01/17 05:29:49 DEBUG : only15: md5 = b79092ba44373dc88025af875178cc52 OK
2022/01/17 05:29:50 DEBUG : both16: md5 = 81412d68baae98343f26542de48bdaa6 OK
2022/01/17 05:29:52 DEBUG : only16: md5 = 90d5323e17bafd45ac2ba5c619844210 OK
2022/01/17 05:29:53 DEBUG : both17: md5 = cfab7129375822338524703b4f7fd13d OK
2022/01/17 05:29:55 DEBUG : only17: md5 = 058cf52b733aaca1b6f2bf2eac4d80f0 OK
2022/01/17 05:29:57 DEBUG : both18: md5 = f4d4014601d51427ac638f77a943d90c OK
2022/01/17 05:29:58 DEBUG : only18: md5 = 1fa2b40a664ea4b0e98fbfa20a994bda OK
2022/01/17 05:30:00 DEBUG : both19: md5 = 2e3375ce0214198af7d1fc201feba51a OK
2022/01/17 05:30:02 DEBUG : only19: md5 = 42fb1264f69d60af9021a5ddd6efd37f OK
2022/01/17 05:30:02 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both0: Unchanged skipping
2022/01/17 05:30:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for checks to finish
2022/01/17 05:30:02 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both11: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both13: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both14: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both15: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both16: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both17: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both18: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both19: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both2: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both3: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both4: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both5: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both6: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both7: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both8: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both9: Unchanged skipping
2022/01/17 05:30:02 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2022/01/17 05:30:02 DEBUG : both12: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both10: Unchanged skipping
2022/01/17 05:30:02 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/01/17 05:30:02 DEBUG : both1: Unchanged skipping
2022/01/17 05:30:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Waiting for transfers to finish
2022/01/17 05:30:04 DEBUG : only0: md5 = d578b4d52e7e1fd4d2406b4da78542f1 OK
2022/01/17 05:30:04 INFO  : only0: Copied (replaced existing)
2022/01/17 05:30:04 DEBUG : only1: md5 = 01bebb005e598ef151a4f3776c8fe1bd OK
2022/01/17 05:30:04 INFO  : only1: Copied (replaced existing)
2022/01/17 05:30:04 DEBUG : only10: md5 = 37d9c4aae4354b87df392e10b44c7c98 OK
2022/01/17 05:30:04 INFO  : only10: Copied (replaced existing)
2022/01/17 05:30:04 DEBUG : only11: md5 = 52ae49633b2d6d6912abccff06c139f8 OK
2022/01/17 05:30:04 INFO  : only11: Copied (replaced existing)
2022/01/17 05:30:05 DEBUG : only12: md5 = 5468ef45f2750d05c5a6d0d9af8d3da8 OK
2022/01/17 05:30:05 INFO  : only12: Copied (replaced existing)
2022/01/17 05:30:05 DEBUG : only13: md5 = 6af3c139b0e5aec4ba0a6a6b0e4acd4b OK
2022/01/17 05:30:05 INFO  : only13: Copied (replaced existing)
2022/01/17 05:30:05 DEBUG : only14: md5 = b73b99a5263d8d002dedb4a7dc829869 OK
2022/01/17 05:30:05 INFO  : only14: Copied (replaced existing)
2022/01/17 05:30:05 DEBUG : only15: md5 = 48e4a477e54760d88bf599e5439288a9 OK
2022/01/17 05:30:05 INFO  : only15: Copied (replaced existing)
2022/01/17 05:30:06 DEBUG : only16: md5 = a93b29d6fed12f0c0cf8b98e4370a095 OK
2022/01/17 05:30:06 INFO  : only16: Copied (replaced existing)
2022/01/17 05:30:06 DEBUG : only18: md5 = 92f412539865cfce928f37e41d2f4ac9 OK
2022/01/17 05:30:06 INFO  : only18: Copied (replaced existing)
2022/01/17 05:30:06 DEBUG : only19: md5 = f112f311ff7b54218bfd835f246e45f2 OK
2022/01/17 05:30:06 INFO  : only19: Copied (replaced existing)
2022/01/17 05:30:06 DEBUG : only17: md5 = 72dff5f2b954e3e4437b0d85c7d15a6a OK
2022/01/17 05:30:06 INFO  : only17: Copied (replaced existing)
2022/01/17 05:30:08 DEBUG : only3: md5 = a110afcb96ae1db9dba09316eb5ca658 OK
2022/01/17 05:30:08 INFO  : only3: Copied (replaced existing)
2022/01/17 05:30:08 DEBUG : only2: md5 = c0566c0488206f63a40aa499fdef050c OK
2022/01/17 05:30:08 INFO  : only2: Copied (replaced existing)
2022/01/17 05:30:08 DEBUG : only5: md5 = 36dd115ae28effe901a8196d497f0f27 OK
2022/01/17 05:30:08 INFO  : only5: Copied (replaced existing)
2022/01/17 05:30:08 DEBUG : only4: md5 = 74d72dd22e87faa237cc6b52d1e4fce5 OK
2022/01/17 05:30:08 INFO  : only4: Copied (replaced existing)
2022/01/17 05:30:09 DEBUG : only6: md5 = e57ade01e3bea58ae512fa490f5088c6 OK
2022/01/17 05:30:09 INFO  : only6: Copied (replaced existing)
2022/01/17 05:30:09 DEBUG : only7: md5 = 5c409ad84f03e05b04b22646d1323ade OK
2022/01/17 05:30:09 INFO  : only7: Copied (replaced existing)
2022/01/17 05:30:09 DEBUG : only9: md5 = 76bf485dd8250e2e65d247e3ac984677 OK
2022/01/17 05:30:09 INFO  : only9: Copied (replaced existing)
2022/01/17 05:30:09 DEBUG : only8: md5 = 1b8c38e8266a4c75f966fab495609098 OK
2022/01/17 05:30:09 INFO  : only8: Copied (replaced existing)
2022/01/17 05:30:09 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncConcurrentTruncate (99.77s)
PASS
2022/01/17 05:30:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cadowub5vuqebey3quginad4': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 13m50.654517169s (try 1/5)