"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5)
2022/03/03 05:59:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5"
2022/03/03 05:59:08 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/03 05:59:08 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao"
2022/03/03 05:59:09 DEBUG : Creating backend with remote "/tmp/rclone3514476916"
=== 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-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:11 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
--- PASS: TestCopyWithDryRun (1.99s)
=== RUN   TestCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:14 DEBUG : sub dir/hello world: md5 = 54a944052436c0290f6492848d642ca4 OK
2022/03/03 05:59:14 INFO  : sub dir/hello world: Copied (new)
2022/03/03 05:59:16 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopy (5.69s)
=== RUN   TestCopyMissingDirectory
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:17 DEBUG : Creating backend with remote "/non-existing"
2022/03/03 05:59:17 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2022/03/03 05:59:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
--- PASS: TestCopyMissingDirectory (0.70s)
=== RUN   TestCopyNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:21 DEBUG : sub dir/hello world: md5 = e357049cf71a1def507c9d35f7b7a25c OK
2022/03/03 05:59:21 INFO  : sub dir/hello world: Copied (new)
2022/03/03 05:59:23 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyNoTraverse (5.68s)
=== RUN   TestCopyCheckFirst
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:23 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Running all checks before starting transfers
2022/03/03 05:59:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:24 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Checks finished, now starting transfers
2022/03/03 05:59:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:26 DEBUG : sub dir/hello world: md5 = 97d805ab1b19e08d56ac21af16aadea0 OK
2022/03/03 05:59:26 INFO  : sub dir/hello world: Copied (new)
2022/03/03 05:59:28 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyCheckFirst (5.65s)
=== RUN   TestSyncNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:29 ERROR : Ignoring --no-traverse with sync
2022/03/03 05:59:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:32 DEBUG : sub dir/hello world: md5 = ff19377ca93536bd00f0d26b16cacdf2 OK
2022/03/03 05:59:32 INFO  : sub dir/hello world: Copied (new)
2022/03/03 05:59:32 DEBUG : Waiting for deletions to finish
2022/03/03 05:59:34 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncNoTraverse (5.79s)
=== RUN   TestCopyWithDepth
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:37 DEBUG : hello world2: md5 = 40914944b73a25b6727dfb3a2ce0aa87 OK
2022/03/03 05:59:37 INFO  : hello world2: Copied (new)
--- PASS: TestCopyWithDepth (3.42s)
=== RUN   TestCopyWithFilesFrom
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:38 DEBUG : hello world2: Excluded
2022/03/03 05:59:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:40 DEBUG : potato2: md5 = 280bb8723a3ca848c6007b54ba8b5177 OK
2022/03/03 05:59:40 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFrom (3.25s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:43 DEBUG : potato2: md5 = 385277bef82a2301cfb87b471dd147a0 OK
2022/03/03 05:59:43 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFromAndNoTraverse (3.16s)
=== RUN   TestCopyEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:45 DEBUG : sub dir2: Making directory
2022/03/03 05:59:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:48 DEBUG : sub dir/hello world: md5 = 80b734016dd19292f7db2da4f777aa19 OK
2022/03/03 05:59:48 INFO  : sub dir/hello world: Copied (new)
2022/03/03 05:59:48 DEBUG : sub dir2: Making directory
2022/03/03 05:59:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': copied 1 directories
2022/03/03 05:59:51 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyEmptyDirectories (7.46s)
=== RUN   TestMoveEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:52 DEBUG : sub dir2: Making directory
2022/03/03 05:59:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 05:59:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 05:59:55 DEBUG : sub dir/hello world: md5 = ef56b0a61304836d289c72afc2f04ad4 OK
2022/03/03 05:59:55 INFO  : sub dir/hello world: Copied (new)
2022/03/03 05:59:55 INFO  : sub dir/hello world: Deleted
2022/03/03 05:59:55 DEBUG : sub dir: Making directory
2022/03/03 05:59:55 DEBUG : sub dir2: Making directory
2022/03/03 05:59:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': copied 2 directories
2022/03/03 05:59:58 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestMoveEmptyDirectories (7.24s)
=== RUN   TestSyncEmptyDirectories
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 05:59:59 DEBUG : sub dir2: Making directory
2022/03/03 06:00:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:02 DEBUG : sub dir/hello world: md5 = 07a1b9f9abf04eb8a3dde4088b5d8250 OK
2022/03/03 06:00:02 INFO  : sub dir/hello world: Copied (new)
2022/03/03 06:00:02 DEBUG : sub dir2: Making directory
2022/03/03 06:00:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': copied 1 directories
2022/03/03 06:00:03 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:06 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestSyncEmptyDirectories (7.58s)
=== RUN   TestServerSideCopy
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:09 DEBUG : sub dir/hello world: md5 = 144d0761a4c321f368290f11766c70f4 OK
2022/03/03 06:00:10 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-paresur7vitewun1xetiruv6"
2022/03/03 06:00:10 DEBUG : Config file has changed externaly - reloading
2022/03/03 06:00:10 DEBUG : Creating backend with remote "TestDrive:crypt/mda4isgdeeni3ihm26olbrdc864iatd97ejck87ptf4866fd8rcbpfn91dt93k7apm5gl91eau90e"
    sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5' -> Encrypted drive 'TestCryptDrive:rclone-test-paresur7vitewun1xetiruv6'
2022/03/03 06:00:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-paresur7vitewun1xetiruv6': Waiting for checks to finish
2022/03/03 06:00:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-paresur7vitewun1xetiruv6': Waiting for transfers to finish
2022/03/03 06:00:12 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/03/03 06:00:12 DEBUG : pacer: Rate limited, increasing sleep to 1.691770349s
2022/03/03 06:00:12 DEBUG : pacer: Reducing sleep to 0s
2022/03/03 06:00:16 INFO  : sub dir/hello world: Copied (server-side copy)
2022/03/03 06:00:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-paresur7vitewun1xetiruv6': Purge remote
2022/03/03 06:00:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestServerSideCopy (13.18s)
=== RUN   TestCopyAfterDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:23 DEBUG : sub dir/hello world: md5 = 0e20df0f4209c8d01bc1895f6c421127 OK
2022/03/03 06:00:23 ERROR : : error listing: directory not found
2022/03/03 06:00:23 DEBUG : Local file system at /tmp/rclone3514476916: Making directory
2022/03/03 06:00:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:26 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyAfterDelete (6.37s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:29 DEBUG : sub dir/hello world: md5 = 367544534951bfcc188ba854080f7ade OK
2022/03/03 06:00:30 DEBUG : Local file system at /tmp/rclone3514476916: Waiting for checks to finish
2022/03/03 06:00:30 DEBUG : Local file system at /tmp/rclone3514476916: Waiting for transfers to finish
2022/03/03 06:00:31 INFO  : sub dir/hello world: Copied (new)
2022/03/03 06:00:32 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
--- PASS: TestCopyRedownload (6.72s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:35 DEBUG : check sum: md5 = c81f869a5b698927cb34668d72317c00 OK
2022/03/03 06:00:35 INFO  : check sum: Copied (new)
2022/03/03 06:00:35 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:36 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2022/03/03 06:00:36 DEBUG : check sum: Size of src and dst objects identical
2022/03/03 06:00:36 DEBUG : check sum: Unchanged skipping
2022/03/03 06:00:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:36 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:36 INFO  : There was nothing to transfer
--- PASS: TestSyncBasedOnCheckSum (3.90s)
=== RUN   TestSyncSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:39 DEBUG : sizeonly: md5 = 37b93e390360263db6b8c3c7a01cd684 OK
2022/03/03 06:00:39 INFO  : sizeonly: Copied (new)
2022/03/03 06:00:39 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:39 DEBUG : sizeonly: Sizes identical
2022/03/03 06:00:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:39 DEBUG : sizeonly: Unchanged skipping
2022/03/03 06:00:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:39 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:39 INFO  : There was nothing to transfer
--- PASS: TestSyncSizeOnly (3.66s)
=== RUN   TestSyncIgnoreSize
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:43 DEBUG : ignore-size: md5 = f1553195ac1e4d4f0ae8792e0d36fff3 OK
2022/03/03 06:00:43 INFO  : ignore-size: Copied (new)
2022/03/03 06:00:43 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:43 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:00:43 DEBUG : ignore-size: Unchanged skipping
2022/03/03 06:00:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:43 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:43 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreSize (4.00s)
=== RUN   TestSyncIgnoreTimes
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:46 DEBUG : existing: md5 = ef9e6c327828e947a5f3304537bfffc9 OK
2022/03/03 06:00:47 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:00:47 DEBUG : existing: Unchanged skipping
2022/03/03 06:00:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:47 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:47 INFO  : There was nothing to transfer
2022/03/03 06:00:47 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2022/03/03 06:00:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:48 DEBUG : existing: md5 = 134a098e967800a902a4d938e8af4d43 OK
2022/03/03 06:00:48 INFO  : existing: Copied (replaced existing)
2022/03/03 06:00:48 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncIgnoreTimes (5.10s)
=== RUN   TestSyncIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:52 DEBUG : existing: md5 = 9cf704c9fbd0186ff60a3a77bfc028ec OK
2022/03/03 06:00:52 INFO  : existing: Copied (new)
2022/03/03 06:00:52 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:52 DEBUG : existing: Destination exists, skipping
2022/03/03 06:00:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:00:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:00:52 DEBUG : Waiting for deletions to finish
2022/03/03 06:00:52 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreExisting (4.01s)
=== RUN   TestSyncIgnoreErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:00:56 DEBUG : b/potato: md5 = 0d453b9749ba17e33f3c906d7d429171 OK
2022/03/03 06:00:59 DEBUG : c/non empty space: md5 = 4f3879aeb01d1679676c5b87aa4e8b53 OK
2022/03/03 06:00:59 DEBUG : d: Making directory
2022/03/03 06:01:01 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:01:01 DEBUG : c/non empty space: Unchanged skipping
2022/03/03 06:01:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:04 DEBUG : a/potato2: md5 = 8ec2c3cb9d289bd607cee7d5045eec47 OK
2022/03/03 06:01:04 INFO  : a/potato2: Copied (new)
2022/03/03 06:01:04 DEBUG : Waiting for deletions to finish
2022/03/03 06:01:04 INFO  : b/potato: Deleted
2022/03/03 06:01:04 INFO  : d: Removing directory
2022/03/03 06:01:05 INFO  : b: Removing directory
2022/03/03 06:01:06 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/03/03 06:01:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': deleted 2 directories
2022/03/03 06:01:07 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded)
2022/03/03 06:01:07 DEBUG : pacer: Rate limited, increasing sleep to 1.93989473s
2022/03/03 06:01:08 DEBUG : pacer: Reducing sleep to 0s
2022/03/03 06:01:10 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/03/03 06:01:11 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncIgnoreErrors (18.47s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:14 DEBUG : empty space: md5 = 5979b22eb7118ec3710e1465067d4d9a OK
2022/03/03 06:01:14 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2022/03/03 06:01:14 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2022/03/03 06:01:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:14 DEBUG : Waiting for deletions to finish
2022/03/03 06:01:15 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2022/03/03 06:01:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:16 DEBUG : empty space: md5 = e6ec5cafa3601b7688c5c03cc7275e08 OK
2022/03/03 06:01:16 INFO  : empty space: Copied (replaced existing)
2022/03/03 06:01:16 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingModtimeOnly (5.36s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
    sync_test.go:577: Can't check this if no hashes supported
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.47s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:20 DEBUG : foo: md5 = db8cd290493b01b0085e053c1604e7a5 OK
2022/03/03 06:01:21 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2022/03/03 06:01:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:22 DEBUG : foo: md5 = b4fa7bfbf445b9968c1ffbc22353d0db OK
2022/03/03 06:01:22 INFO  : foo: Copied (replaced existing)
2022/03/03 06:01:22 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncDoesntUpdateModtime (5.09s)
=== RUN   TestSyncAfterAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:25 DEBUG : empty space: md5 = 0405d99e83b6273b5da25b967bbbe838 OK
2022/03/03 06:01:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:25 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:01:25 DEBUG : empty space: Unchanged skipping
2022/03/03 06:01:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:27 DEBUG : potato: md5 = d4a350e314b2bac4fcd3782e88d04d51 OK
2022/03/03 06:01:27 INFO  : potato: Copied (new)
2022/03/03 06:01:27 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterAddingAFile (5.73s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:31 DEBUG : potato: md5 = 94e9645d031d0cf638daf37d89a61dc2 OK
2022/03/03 06:01:31 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2022/03/03 06:01:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:32 DEBUG : potato: md5 = ae8607ebc99a6ba2fdc592f289ac7560 OK
2022/03/03 06:01:32 INFO  : potato: Copied (replaced existing)
2022/03/03 06:01:32 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingFilesSizeOnly (4.77s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:35 DEBUG : potato: md5 = ac181aaedde7c6a9356d22aa651a6f24 OK
2022/03/03 06:01:36 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC
2022/03/03 06:01:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:37 DEBUG : potato: md5 = f8560564a4ceaa50946350e4412838fa OK
2022/03/03 06:01:37 INFO  : potato: Copied (replaced existing)
2022/03/03 06:01:37 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncAfterChangingContentsOnly (4.95s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:40 DEBUG : potato: md5 = 4852d79e17ed300d8e6c7257ffb00167 OK
2022/03/03 06:01:42 DEBUG : empty space: md5 = 33d0785ccc6d2e18256697af31663d88 OK
2022/03/03 06:01:42 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2022/03/03 06:01:42 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:01:42 DEBUG : empty space: Unchanged skipping
2022/03/03 06:01:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:42 DEBUG : Waiting for deletions to finish
2022/03/03 06:01:42 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.82s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:46 DEBUG : potato: md5 = 2f95602c78ebb5ff3693cc206f8633fe OK
2022/03/03 06:01:48 DEBUG : empty space: md5 = f634629f1af6cf67f42040f79aa025e5 OK
2022/03/03 06:01:48 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:01:48 DEBUG : empty space: Unchanged skipping
2022/03/03 06:01:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:01:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:01:50 DEBUG : potato2: md5 = 8b76b1a7a4a32912ce92174758e4b71d OK
2022/03/03 06:01:50 INFO  : potato2: Copied (new)
2022/03/03 06:01:50 DEBUG : Waiting for deletions to finish
2022/03/03 06:01:51 INFO  : potato: Deleted
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (8.11s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:01:55 DEBUG : b/potato: md5 = 9853d50398178a15f23477f5ab72444b OK
2022/03/03 06:01:58 DEBUG : c/non empty space: md5 = d92439dc29e49bf149b0202e292c52f3 OK
2022/03/03 06:01:58 DEBUG : d: Making directory
2022/03/03 06:01:59 DEBUG : d/e: Making directory
2022/03/03 06:02:01 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:02:01 DEBUG : c/non empty space: Unchanged skipping
2022/03/03 06:02:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:05 DEBUG : a/potato2: md5 = b3a1bb899cd405e8b616860d9dd97284 OK
2022/03/03 06:02:05 INFO  : a/potato2: Copied (new)
2022/03/03 06:02:05 DEBUG : Waiting for deletions to finish
2022/03/03 06:02:05 INFO  : b/potato: Deleted
2022/03/03 06:02:05 INFO  : d/e: Removing directory
2022/03/03 06:02:06 INFO  : d: Removing directory
2022/03/03 06:02:07 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8"
2022/03/03 06:02:07 INFO  : b: Removing directory
2022/03/03 06:02:08 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/03/03 06:02:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': deleted 3 directories
2022/03/03 06:02:11 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/03/03 06:02:12 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (20.40s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:02:16 DEBUG : b/potato: md5 = 638f3964c39460701a78e9131ba0c0fc OK
2022/03/03 06:02:18 DEBUG : c/non empty space: md5 = 1fefec09e87f0bdad8c1f39b98e13924 OK
2022/03/03 06:02:18 DEBUG : d: Making directory
2022/03/03 06:02:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:20 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:02:20 DEBUG : c/non empty space: Unchanged skipping
2022/03/03 06:02:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:23 DEBUG : a/potato2: md5 = 77c8fc9ac0847b0ded2f5b33a9b54e4a OK
2022/03/03 06:02:23 INFO  : a/potato2: Copied (new)
2022/03/03 06:02:23 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': not deleting files as there were IO errors
2022/03/03 06:02:23 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': not deleting directories as there were IO errors
2022/03/03 06:02:27 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s"
2022/03/03 06:02:28 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4"
2022/03/03 06:02:29 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (17.11s)
=== RUN   TestSyncDeleteAfter
--- PASS: TestSyncDeleteAfter (0.00s)
=== RUN   TestSyncDeleteDuring
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:02:32 DEBUG : potato: md5 = f8d9878ce5cf5f310fb96a86e1e8bfab OK
2022/03/03 06:02:33 DEBUG : empty space: md5 = 5fc42e212dae46fb9296b2525c1cdf04 OK
2022/03/03 06:02:34 DEBUG : Waiting for deletions to finish
2022/03/03 06:02:34 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:02:34 DEBUG : empty space: Unchanged skipping
2022/03/03 06:02:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:35 INFO  : potato: Deleted
2022/03/03 06:02:36 DEBUG : potato2: md5 = e0d692d5a127c3b91c14b1baf260ccbc OK
2022/03/03 06:02:36 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteDuring (7.56s)
=== RUN   TestSyncDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:02:39 DEBUG : potato: md5 = 993e8f61287898b906077da3a92dfc13 OK
2022/03/03 06:02:41 DEBUG : empty space: md5 = 6df82f8d84943af44707d888d8fb9c40 OK
2022/03/03 06:02:41 DEBUG : Waiting for deletions to finish
2022/03/03 06:02:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:42 INFO  : potato: Deleted
2022/03/03 06:02:42 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:02:42 DEBUG : empty space: Unchanged skipping
2022/03/03 06:02:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:44 DEBUG : potato2: md5 = e2d6487e8df606ad38a63114fa594b94 OK
2022/03/03 06:02:44 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteBefore (8.27s)
=== RUN   TestCopyDeleteBefore
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:02:48 DEBUG : potato: md5 = b0b74e94843cfe1d66454509a07474aa OK
2022/03/03 06:02:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:50 DEBUG : potato2: md5 = 1ab4e0c8cf5c4c68e7f57f10e0ce797c OK
2022/03/03 06:02:50 INFO  : potato2: Copied (new)
--- PASS: TestCopyDeleteBefore (5.72s)
=== RUN   TestSyncWithExclude
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:02:53 DEBUG : potato2: md5 = 1d52449db7fa40c3da202621ef7e598d OK
2022/03/03 06:02:55 DEBUG : empty space: md5 = 04815e27424418ab5d683ce974ce6285 OK
2022/03/03 06:02:55 DEBUG : enormous: Excluded
2022/03/03 06:02:55 DEBUG : potato2: Excluded
2022/03/03 06:02:56 DEBUG : potato2: Excluded from sync (and deletion)
2022/03/03 06:02:56 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:02:56 DEBUG : empty space: Unchanged skipping
2022/03/03 06:02:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:02:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:02:56 DEBUG : Waiting for deletions to finish
2022/03/03 06:02:56 INFO  : There was nothing to transfer
2022/03/03 06:02:56 DEBUG : enormous: Excluded
2022/03/03 06:02:56 DEBUG : potato2: Excluded
2022/03/03 06:02:56 DEBUG : potato2: Excluded from sync (and deletion)
2022/03/03 06:02:56 DEBUG : Local file system at /tmp/rclone3514476916: Waiting for checks to finish
2022/03/03 06:02:56 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2022/03/03 06:02:56 DEBUG : empty space: Unchanged skipping
2022/03/03 06:02:56 DEBUG : Local file system at /tmp/rclone3514476916: Waiting for transfers to finish
2022/03/03 06:02:56 DEBUG : Waiting for deletions to finish
2022/03/03 06:02:56 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExclude (6.36s)
=== RUN   TestSyncWithExcludeAndDeleteExcluded
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:02:59 DEBUG : potato2: md5 = 9bbbfe454ec59fc7bccd43313051ed67 OK
2022/03/03 06:03:01 DEBUG : empty space: md5 = 7dfeee4797a9c275b43a209e5e7d7d76 OK
2022/03/03 06:03:03 DEBUG : enormous: md5 = 9538fddb14e2f2f259981b222dde7f68 OK
2022/03/03 06:03:03 DEBUG : enormous: Excluded
2022/03/03 06:03:03 DEBUG : potato2: Excluded
2022/03/03 06:03:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:04 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:03:04 DEBUG : empty space: Unchanged skipping
2022/03/03 06:03:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:04 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:04 INFO  : potato2: Deleted
2022/03/03 06:03:04 INFO  : enormous: Deleted
2022/03/03 06:03:04 INFO  : There was nothing to transfer
2022/03/03 06:03:05 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms)
2022/03/03 06:03:05 DEBUG : empty space: Unchanged skipping
2022/03/03 06:03:05 DEBUG : Local file system at /tmp/rclone3514476916: Waiting for checks to finish
2022/03/03 06:03:05 DEBUG : Local file system at /tmp/rclone3514476916: Waiting for transfers to finish
2022/03/03 06:03:05 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:05 INFO  : enormous: Deleted
2022/03/03 06:03:05 INFO  : potato2: Deleted
2022/03/03 06:03:05 INFO  : There was nothing to transfer
--- PASS: TestSyncWithExcludeAndDeleteExcluded (8.00s)
=== RUN   TestSyncWithUpdateOlder
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:03:08 DEBUG : one: md5 = 21a887e9b94282f90f48e104b7f4ed9a OK
2022/03/03 06:03:09 DEBUG : two: md5 = a65ab4c62c581403aad01b9e7d1de08a OK
2022/03/03 06:03:11 DEBUG : three: md5 = 7db1918ff1cc10b81fd5fd469346bc13 OK
2022/03/03 06:03:12 DEBUG : four: md5 = f1144f8c7607cc08a9e02147bc9b0fbe OK
2022/03/03 06:03:13 DEBUG : four: Sizes differ (src 4 vs dst 8)
2022/03/03 06:03:13 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring
2022/03/03 06:03:13 DEBUG : one: Destination is newer than source, skipping
2022/03/03 06:03:13 DEBUG : three: Sizes identical
2022/03/03 06:03:13 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping
2022/03/03 06:03:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:14 DEBUG : four: md5 = 5b0b7e4bf84d5a7e2feb04416f26556e OK
2022/03/03 06:03:14 INFO  : four: Copied (replaced existing)
2022/03/03 06:03:14 DEBUG : two: md5 = 11b2d5c60c8170a2b0bdb0e377714e03 OK
2022/03/03 06:03:14 INFO  : two: Copied (replaced existing)
2022/03/03 06:03:14 DEBUG : five: md5 = 0c35d63db0cea96e8c7192992e201403 OK
2022/03/03 06:03:14 INFO  : five: Copied (new)
2022/03/03 06:03:14 DEBUG : Waiting for deletions to finish
    sync_test.go:992: Skip test with --checksum as no hashes supported
--- PASS: TestSyncWithUpdateOlder (12.24s)
=== 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-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
    sync_test.go:1058: Can track renames: false
2022/03/03 06:03:18 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Ignoring --track-renames as the source and destination do not have a common hash
2022/03/03 06:03:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:20 DEBUG : yam: md5 = 46352d779c4fccdf2ed64550b3dba9a2 OK
2022/03/03 06:03:20 INFO  : yam: Copied (new)
2022/03/03 06:03:21 DEBUG : potato: md5 = 2aa57097c5624e40f82cff6ba454e695 OK
2022/03/03 06:03:21 INFO  : potato: Copied (new)
2022/03/03 06:03:21 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:21 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Ignoring --track-renames as the source and destination do not have a common hash
2022/03/03 06:03:21 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:03:21 DEBUG : potato: Unchanged skipping
2022/03/03 06:03:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:23 DEBUG : yaml: md5 = 9b3df093346170767de7def15b3e3432 OK
2022/03/03 06:03:23 INFO  : yaml: Copied (new)
2022/03/03 06:03:23 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:23 INFO  : yam: Deleted
--- PASS: TestSyncWithTrackRenames (7.23s)
=== RUN   TestParseRenamesStrategyModtime
--- PASS: TestParseRenamesStrategyModtime (0.00s)
=== RUN   TestRenamesStrategyModtime
--- PASS: TestRenamesStrategyModtime (0.00s)
=== RUN   TestSyncWithTrackRenamesStrategyModtime
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
    sync_test.go:1127: Can track renames: true
2022/03/03 06:03:26 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Making map for --track-renames
2022/03/03 06:03:26 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Finished making map for --track-renames
2022/03/03 06:03:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for renames to finish
2022/03/03 06:03:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:27 DEBUG : potato: md5 = 68640c23a4fa206129901c122d1fe06c OK
2022/03/03 06:03:27 INFO  : potato: Copied (new)
2022/03/03 06:03:28 DEBUG : yam: md5 = d8b64562ba547f8240cdc1c872375712 OK
2022/03/03 06:03:28 INFO  : yam: Copied (new)
2022/03/03 06:03:28 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:28 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Making map for --track-renames
2022/03/03 06:03:28 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:03:28 DEBUG : potato: Unchanged skipping
2022/03/03 06:03:28 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Finished making map for --track-renames
2022/03/03 06:03:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for renames to finish
2022/03/03 06:03:29 INFO  : yam: Moved (server-side) to: yaml
2022/03/03 06:03:29 INFO  : yaml: Renamed from "yam"
2022/03/03 06:03:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:29 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:29 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyModtime (5.78s)
=== RUN   TestSyncWithTrackRenamesStrategyLeaf
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
    sync_test.go:1163: Can track renames: true
2022/03/03 06:03:32 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Making map for --track-renames
2022/03/03 06:03:32 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Finished making map for --track-renames
2022/03/03 06:03:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for renames to finish
2022/03/03 06:03:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:34 DEBUG : potato: md5 = 6212ea2ff8bde7dab8476a6d98e52c03 OK
2022/03/03 06:03:34 INFO  : potato: Copied (new)
2022/03/03 06:03:34 DEBUG : sub/yam: md5 = 49ac97d11513a42a92a3b165b54a35ad OK
2022/03/03 06:03:34 INFO  : sub/yam: Copied (new)
2022/03/03 06:03:34 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:35 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:03:35 DEBUG : potato: Unchanged skipping
2022/03/03 06:03:35 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Making map for --track-renames
2022/03/03 06:03:35 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Finished making map for --track-renames
2022/03/03 06:03:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for renames to finish
2022/03/03 06:03:37 INFO  : sub/yam: Moved (server-side) to: yam
2022/03/03 06:03:37 INFO  : yam: Renamed from "sub/yam"
2022/03/03 06:03:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:37 DEBUG : Waiting for deletions to finish
2022/03/03 06:03:37 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenamesStrategyLeaf (8.67s)
=== RUN   TestMoveWithDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:03:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:43 DEBUG : sub dir/hello world: md5 = 0d12f397dca830f05ee2ae41dc4e69b7 OK
2022/03/03 06:03:43 INFO  : sub dir/hello world: Copied (new)
2022/03/03 06:03:43 INFO  : sub dir/hello world: Deleted
2022/03/03 06:03:45 DEBUG : nested/sub dir/file: md5 = dd4b4acc2498404bf07b63b35064eb47 OK
2022/03/03 06:03:45 INFO  : nested/sub dir/file: Copied (new)
2022/03/03 06:03:45 INFO  : nested/sub dir/file: Deleted
2022/03/03 06:03:45 INFO  : sub dir: Removing directory
2022/03/03 06:03:45 INFO  : nested/sub dir: Removing directory
2022/03/03 06:03:45 INFO  : nested: Removing directory
2022/03/03 06:03:45 DEBUG : Local file system at /tmp/rclone3514476916: deleted 3 directories
2022/03/03 06:03:48 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2022/03/03 06:03:49 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2022/03/03 06:03:50 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithDeleteEmptySrcDirs (11.72s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:03:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:03:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:03:55 DEBUG : sub dir/hello world: md5 = 92ac421fdf29d036439f67de115965be OK
2022/03/03 06:03:55 INFO  : sub dir/hello world: Copied (new)
2022/03/03 06:03:55 INFO  : sub dir/hello world: Deleted
2022/03/03 06:03:57 DEBUG : nested/sub dir/file: md5 = feb4cffa1fc369ecf7a07e65ad2d22d9 OK
2022/03/03 06:03:57 INFO  : nested/sub dir/file: Copied (new)
2022/03/03 06:03:57 INFO  : nested/sub dir/file: Deleted
2022/03/03 06:04:00 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo"
2022/03/03 06:04:01 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk"
2022/03/03 06:04:02 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0"
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (11.29s)
=== RUN   TestMoveWithIgnoreExisting
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:04:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:04:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:04:05 DEBUG : existing-b: md5 = 20fa5d0ff0a99f0aa780bd360cb3686a OK
2022/03/03 06:04:05 INFO  : existing-b: Copied (new)
2022/03/03 06:04:05 INFO  : existing-b: Deleted
2022/03/03 06:04:05 DEBUG : existing: md5 = ebc9f92f1479b85888d0dfea7499f47e OK
2022/03/03 06:04:05 INFO  : existing: Copied (new)
2022/03/03 06:04:05 INFO  : existing: Deleted
2022/03/03 06:04:06 DEBUG : existing: Destination exists, skipping
2022/03/03 06:04:06 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set
2022/03/03 06:04:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:04:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:04:06 INFO  : There was nothing to transfer
--- PASS: TestMoveWithIgnoreExisting (4.97s)
=== RUN   TestServerSideMove
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:04:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8"
2022/03/03 06:04:08 DEBUG : Creating backend with remote "TestDrive:crypt/l6tj8cop6d4k4q1kfo6dd9p7jbbvlcsfqudsiaj9o6u3th989hmivscul5ke8e89hf2pk6i0hnh2a"
2022/03/03 06:04:12 DEBUG : potato2: md5 = 3b92b469be2d239b781f533e901ca2a9 OK
2022/03/03 06:04:14 DEBUG : empty space: md5 = 780c9cf7ad0a150e220686967f35bffc OK
2022/03/03 06:04:15 DEBUG : potato3: md5 = a1c4dc6e8637c9400be62b66f628adef OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5' -> Encrypted drive 'TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8'
2022/03/03 06:04:18 DEBUG : empty space: md5 = 0896c6732512241acda91296031c4881 OK
2022/03/03 06:04:20 DEBUG : potato3: md5 = 65e9142f7db11efd73414f325a6d55f8 OK
2022/03/03 06:04:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8': Using server-side directory move
2022/03/03 06:04:20 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2022/03/03 06:04:20 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2022/03/03 06:04:20 DEBUG : empty space: Unchanged skipping
2022/03/03 06:04:20 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/03/03 06:04:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8': Waiting for checks to finish
2022/03/03 06:04:21 INFO  : empty space: Deleted
2022/03/03 06:04:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8': Waiting for transfers to finish
2022/03/03 06:04:21 INFO  : potato3: Deleted
2022/03/03 06:04:21 INFO  : potato2: Moved (server-side)
2022/03/03 06:04:22 INFO  : potato3: Moved (server-side)
2022/03/03 06:04:22 INFO  : There was nothing to transfer
2022/03/03 06:04:22 DEBUG : Config file has changed externaly - reloading
2022/03/03 06:04:22 DEBUG : TestDrive: Loaded fresh token from config file
2022/03/03 06:04:22 DEBUG : TestDrive: Loaded fresh token from config file
2022/03/03 06:04:22 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nuqiyog1luwomis9cikegor3"
2022/03/03 06:04:23 DEBUG : Creating backend with remote "TestDrive:crypt/ua61ujqkcr47lnvhde2j71hh9bnlv3012a24kp6k0d9d3cid7p6bleija1c2cmdd622psu4jagpfo"
2022/03/03 06:04:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nuqiyog1luwomis9cikegor3': Using server-side directory move
2022/03/03 06:04:25 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-nuqiyog1luwomis9cikegor3': Server side directory move succeeded
2022/03/03 06:04:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nuqiyog1luwomis9cikegor3': Purge remote
2022/03/03 06:04:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-viyuzuv0dibemaz9veruyaw8': Purge remote
2022/03/03 06:04:27 purge failed: directory not found
--- PASS: TestServerSideMove (19.31s)
=== RUN   TestServerSideMoveWithFilter
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:04:27 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tanidol1raxibin4gejases9"
2022/03/03 06:04:27 DEBUG : Creating backend with remote "TestDrive:crypt/6jkak2953u60o5928sekpchr8qrcu5aoh31n757seh1gdof4tu59a9jejsacc42amvauinn2gnntm"
2022/03/03 06:04:30 DEBUG : potato2: md5 = 7e9bd5da9a8ccd532e3e993ef3d6e066 OK
2022/03/03 06:04:32 DEBUG : empty space: md5 = 1fbd941e3d0c890e7258da902a4725d4 OK
2022/03/03 06:04:33 DEBUG : potato3: md5 = 8e5a35bf8430bf953c6c3799620f5576 OK
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5' -> Encrypted drive 'TestCryptDrive:rclone-test-tanidol1raxibin4gejases9'
2022/03/03 06:04:36 DEBUG : empty space: md5 = c8b36e41368f1c09e9e37cdd83c9a957 OK
2022/03/03 06:04:38 DEBUG : potato3: md5 = fc9218575dbbac41fc05d0e669416d78 OK
2022/03/03 06:04:38 DEBUG : empty space: Excluded from sync (and deletion)
2022/03/03 06:04:38 DEBUG : empty space: Excluded from sync (and deletion)
2022/03/03 06:04:38 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/03/03 06:04:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tanidol1raxibin4gejases9': Waiting for checks to finish
2022/03/03 06:04:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tanidol1raxibin4gejases9': Waiting for transfers to finish
2022/03/03 06:04:39 INFO  : potato3: Deleted
2022/03/03 06:04:39 INFO  : potato2: Moved (server-side)
2022/03/03 06:04:40 INFO  : potato3: Moved (server-side)
2022/03/03 06:04:40 INFO  : There was nothing to transfer
2022/03/03 06:04:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-dudinaj8gexonab6sotadof6"
2022/03/03 06:04:41 DEBUG : Creating backend with remote "TestDrive:crypt/9g40m8t0412ubsu0klhc5ipp4pqm0b9islk1q8m5rtqtjfjcaur1ue8mafknro14c0lqqeei7t3r8"
2022/03/03 06:04:42 DEBUG : empty space: Excluded from sync (and deletion)
2022/03/03 06:04:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dudinaj8gexonab6sotadof6': Waiting for checks to finish
2022/03/03 06:04:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dudinaj8gexonab6sotadof6': Waiting for transfers to finish
2022/03/03 06:04:44 INFO  : potato3: Moved (server-side)
2022/03/03 06:04:44 INFO  : potato2: Moved (server-side)
2022/03/03 06:04:44 INFO  : There was nothing to transfer
2022/03/03 06:04:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dudinaj8gexonab6sotadof6': Purge remote
2022/03/03 06:04:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tanidol1raxibin4gejases9': Purge remote
--- PASS: TestServerSideMoveWithFilter (20.40s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:04:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0"
2022/03/03 06:04:48 DEBUG : Creating backend with remote "TestDrive:crypt/888p0baapor2384h9hja89micna5fug12e3mu7jh4konduld0l0i8e595lljo4pmt988ifns21t7k"
2022/03/03 06:04:51 DEBUG : potato2: md5 = e8f729dd9d391dc16ad7eec4c5067feb OK
2022/03/03 06:04:52 DEBUG : empty space: md5 = a8081e3ae0ee8e46e166e57053949080 OK
2022/03/03 06:04:54 DEBUG : potato3: md5 = 2a33b3fdb28b3637392e020776364a9b OK
2022/03/03 06:04:54 DEBUG : tomatoDir: Making directory
    sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5' -> Encrypted drive 'TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0'
2022/03/03 06:04:58 DEBUG : empty space: md5 = 90aa04a92c70ce65e458dd50977783b9 OK
2022/03/03 06:05:00 DEBUG : potato3: md5 = 9bcee4420b47aaa8a19fb3cf984054f5 OK
2022/03/03 06:05:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0': Using server-side directory move
2022/03/03 06:05:00 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2022/03/03 06:05:01 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms)
2022/03/03 06:05:01 DEBUG : empty space: Unchanged skipping
2022/03/03 06:05:01 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2022/03/03 06:05:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0': Waiting for checks to finish
2022/03/03 06:05:01 INFO  : empty space: Deleted
2022/03/03 06:05:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0': Waiting for transfers to finish
2022/03/03 06:05:02 INFO  : potato3: Deleted
2022/03/03 06:05:02 INFO  : potato2: Moved (server-side)
2022/03/03 06:05:02 INFO  : potato3: Moved (server-side)
2022/03/03 06:05:02 INFO  : tomatoDir: Removing directory
2022/03/03 06:05:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': deleted 1 directories
2022/03/03 06:05:03 INFO  : There was nothing to transfer
2022/03/03 06:05:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vewenok3najawoc1libizut2"
2022/03/03 06:05:04 DEBUG : Creating backend with remote "TestDrive:crypt/rat4gkvbgl469rh9seomui18o3c6fj5jmoiudr6kk8n6hf13bb39sos7c7pjec4lee44qdmto2os2"
2022/03/03 06:05:06 DEBUG : tomatoDir: Making directory
2022/03/03 06:05:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vewenok3najawoc1libizut2': Using server-side directory move
2022/03/03 06:05:07 INFO  : Encrypted drive 'TestCryptDrive:rclone-test-vewenok3najawoc1libizut2': Server side directory move succeeded
2022/03/03 06:05:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vewenok3najawoc1libizut2': Purge remote
2022/03/03 06:05:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cojicax8qequrex3wihabiq0': Purge remote
2022/03/03 06:05:10 purge failed: directory not found
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (22.96s)
=== RUN   TestServerSideMoveOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
    sync_test.go:1399: Skipping test as remote supports DirMove
--- SKIP: TestServerSideMoveOverlap (0.60s)
=== RUN   TestSyncOverlap
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:05:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/rclone-sync-test"
2022/03/03 06:05:11 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0"
--- PASS: TestSyncOverlap (2.35s)
=== RUN   TestSyncCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:05:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:05:14 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:05:15 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/CompareDest"
2022/03/03 06:05:15 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/gveqi14airsml4bgu7krj116o8"
2022/03/03 06:05:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:05:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:05:20 DEBUG : one: md5 = 0820019e06c601b33915d4fe04572ffc OK
2022/03/03 06:05:20 INFO  : one: Copied (new)
2022/03/03 06:05:20 DEBUG : Waiting for deletions to finish
2022/03/03 06:05:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:05:22 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/03/03 06:05:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:05:23 DEBUG : one: md5 = d8c9458d1909cbded76ea94cd217cee9 OK
2022/03/03 06:05:23 INFO  : one: Copied (replaced existing)
2022/03/03 06:05:23 DEBUG : Waiting for deletions to finish
2022/03/03 06:05:25 DEBUG : dst/one: md5 = 62a76800b01ffbcdef85f46a082ba324 OK
2022/03/03 06:05:28 DEBUG : CompareDest/one: md5 = 2575b9ba20fff344e89586a031c308c8 OK
2022/03/03 06:05:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:05:30 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:05:30 DEBUG : one: Destination found in --compare-dest, skipping
2022/03/03 06:05:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:05:30 DEBUG : Waiting for deletions to finish
2022/03/03 06:05:30 INFO  : There was nothing to transfer
2022/03/03 06:05:32 DEBUG : CompareDest/two: md5 = 20d1a98d0a5667a6cce88f34de77456d OK
2022/03/03 06:05:33 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:05:33 DEBUG : two: Destination found in --compare-dest, skipping
2022/03/03 06:05:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:05:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:05:33 DEBUG : one: Destination found in --compare-dest, skipping
2022/03/03 06:05:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:05:33 DEBUG : Waiting for deletions to finish
2022/03/03 06:05:33 INFO  : There was nothing to transfer
2022/03/03 06:05:35 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:05:35 DEBUG : two: Destination found in --compare-dest, skipping
2022/03/03 06:05:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:05:35 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:05:35 DEBUG : one: Destination found in --compare-dest, skipping
2022/03/03 06:05:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:05:35 DEBUG : Waiting for deletions to finish
2022/03/03 06:05:35 INFO  : There was nothing to transfer
    sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test
2022/03/03 06:05:37 DEBUG : two: Sizes differ (src 5 vs dst 3)
2022/03/03 06:05:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:05:37 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:05:37 DEBUG : one: Destination found in --compare-dest, skipping
2022/03/03 06:05:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:05:39 DEBUG : two: md5 = c6f7e585d22b975e4c4f6edde840c172 OK
2022/03/03 06:05:39 INFO  : two: Copied (new)
2022/03/03 06:05:39 DEBUG : Waiting for deletions to finish
2022/03/03 06:05:43 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:05:43 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:05:44 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:05:44 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncCompareDest (31.03s)
=== RUN   TestSyncMultipleCompareDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:05:47 DEBUG : pre-dest1/1: md5 = 54e881d91e30411499f39637e9389412 OK
2022/03/03 06:05:50 DEBUG : pre-dest2/2: md5 = 88c9365bee62f9e402ffc007780c80d6 OK
2022/03/03 06:05:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dest"
2022/03/03 06:05:50 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/rg03c1jvnehrrc617i0lnqjddc"
2022/03/03 06:05:52 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/pre-dest1"
2022/03/03 06:05:52 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/bbnblvh6k061ssopqrp18kd7gc"
2022/03/03 06:05:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/pre-dest2"
2022/03/03 06:05:53 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/dgicm1h6b5ejvlltm8eeif0bnk"
2022/03/03 06:05:55 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:05:55 DEBUG : 1: Destination found in --compare-dest, skipping
2022/03/03 06:05:55 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:05:55 DEBUG : 2: Destination found in --compare-dest, skipping
2022/03/03 06:05:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dest': Waiting for checks to finish
2022/03/03 06:05:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dest': Waiting for transfers to finish
2022/03/03 06:05:58 DEBUG : 3: md5 = 62054fa2c6e07879a13bc315427acf9a OK
2022/03/03 06:05:58 INFO  : 3: Copied (new)
2022/03/03 06:05:58 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:02 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc"
2022/03/03 06:06:03 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro"
2022/03/03 06:06:04 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg"
--- PASS: TestSyncMultipleCompareDest (20.41s)
=== RUN   TestSyncCopyDest
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:06:05 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:06:05 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:06:07 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/CopyDest"
2022/03/03 06:06:07 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/d09o6po3f7bm6ce32vdgs8h9ls"
2022/03/03 06:06:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:06:12 DEBUG : one: md5 = b03bce47131b3a3e76b16af5dcc5b1cd OK
2022/03/03 06:06:12 INFO  : one: Copied (new)
2022/03/03 06:06:12 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:13 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/03/03 06:06:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:06:15 DEBUG : one: md5 = 8bc58d117bb4b0ed2e8b01a9fdb716b1 OK
2022/03/03 06:06:15 INFO  : one: Copied (replaced existing)
2022/03/03 06:06:15 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:17 DEBUG : dst/one: md5 = 4859a286cf9defef1b39f19920eefb24 OK
2022/03/03 06:06:19 DEBUG : CopyDest/one: md5 = 424bd9c916c73bab5a48701540f10555 OK
2022/03/03 06:06:20 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/BackupDir"
2022/03/03 06:06:20 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/s6dbk3lfi7c9kfvo6j7bla9m0g"
2022/03/03 06:06:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:23 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:23 DEBUG : one: Sizes differ (src 5 vs dst 3)
2022/03/03 06:06:25 INFO  : one: Moved (server-side)
2022/03/03 06:06:26 INFO  : one: Copied (server-side copy)
2022/03/03 06:06:26 DEBUG : one: Destination found in --copy-dest, using server-side copy
2022/03/03 06:06:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:06:26 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:29 DEBUG : CopyDest/two: md5 = d1ee590e40c9734db68c1e52f8d82420 OK
2022/03/03 06:06:30 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:31 INFO  : two: Copied (server-side copy)
2022/03/03 06:06:31 DEBUG : two: Destination found in --copy-dest, using server-side copy
2022/03/03 06:06:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:32 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:32 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:32 DEBUG : one: Unchanged skipping
2022/03/03 06:06:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:06:32 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:33 DEBUG : one: Unchanged skipping
2022/03/03 06:06:33 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:33 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:33 DEBUG : two: Unchanged skipping
2022/03/03 06:06:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:06:33 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:33 INFO  : There was nothing to transfer
2022/03/03 06:06:35 DEBUG : CopyDest/three: md5 = da0aaa6f1f8aeb97ba47b739904cf32e OK
2022/03/03 06:06:36 DEBUG : three: Sizes differ (src 7 vs dst 5)
2022/03/03 06:06:36 DEBUG : three: Destination not found in --copy-dest
2022/03/03 06:06:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:37 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:37 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:37 DEBUG : one: Unchanged skipping
2022/03/03 06:06:37 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:37 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2022/03/03 06:06:37 DEBUG : two: Unchanged skipping
2022/03/03 06:06:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:06:38 DEBUG : three: md5 = 1b564e257ebca035ec1ec315f1aec59c OK
2022/03/03 06:06:38 INFO  : three: Copied (new)
2022/03/03 06:06:38 DEBUG : Waiting for deletions to finish
2022/03/03 06:06:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2022/03/03 06:06:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:06:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:06:45 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:06:45 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:06:45 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os"
2022/03/03 06:06:46 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
--- PASS: TestSyncCopyDest (42.23s)
=== RUN   TestSyncBackupDir
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:06:50 DEBUG : dst/one: md5 = 75a46f01dcf7f3c3ba89add86b2f6f47 OK
2022/03/03 06:06:51 DEBUG : dst/two: md5 = a4f8c045148fbcb38b8566ae2f0851a3 OK
2022/03/03 06:06:53 DEBUG : dst/three.txt: md5 = a0b2997512ff088bc8c241429dba932e OK
2022/03/03 06:06:54 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:06:54 DEBUG : Config file has changed externaly - reloading
2022/03/03 06:06:54 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:06:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/backup"
2022/03/03 06:06:55 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/1nrff024r7pq65ecp72fc28jb0"
2022/03/03 06:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:06:57 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/03/03 06:06:57 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:06:57 DEBUG : two: Unchanged skipping
2022/03/03 06:06:59 INFO  : one: Moved (server-side)
2022/03/03 06:06:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:07:01 DEBUG : one: md5 = a48f2a926688425acad524f5dce1efab OK
2022/03/03 06:07:01 INFO  : one: Copied (new)
2022/03/03 06:07:01 DEBUG : Waiting for deletions to finish
2022/03/03 06:07:02 INFO  : three.txt: Moved (server-side)
2022/03/03 06:07:02 INFO  : three.txt: Moved into backup dir
2022/03/03 06:07:04 DEBUG : dst/three.txt: md5 = 45f042836a3b3895fccebdae5750fcaa OK
2022/03/03 06:07:05 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/03/03 06:07:05 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:07:05 DEBUG : two: Unchanged skipping
2022/03/03 06:07:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:07:06 INFO  : one: Deleted
2022/03/03 06:07:07 INFO  : one: Moved (server-side)
2022/03/03 06:07:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:07:09 DEBUG : one: md5 = f59f75eef71c687c3a9cb8398711e5be OK
2022/03/03 06:07:09 INFO  : one: Copied (new)
2022/03/03 06:07:09 DEBUG : Waiting for deletions to finish
2022/03/03 06:07:09 INFO  : three.txt: Deleted
2022/03/03 06:07:10 INFO  : three.txt: Moved (server-side)
2022/03/03 06:07:10 INFO  : three.txt: Moved into backup dir
2022/03/03 06:07:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:07:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:07:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:07:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/03/03 06:07:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:07:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
--- PASS: TestSyncBackupDir (29.47s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:07:20 DEBUG : dst/one: md5 = 7612b6506a63d6c6a24d21cc2aa82b22 OK
2022/03/03 06:07:21 DEBUG : dst/two: md5 = 71631ddf058ef24424a7f2bc91164998 OK
2022/03/03 06:07:23 DEBUG : dst/three.txt: md5 = a02ed89cccace69c729a60ff05e08372 OK
2022/03/03 06:07:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:07:24 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:07:25 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/backup"
2022/03/03 06:07:25 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/1nrff024r7pq65ecp72fc28jb0"
2022/03/03 06:07:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:07:27 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/03/03 06:07:27 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:07:27 DEBUG : two: Unchanged skipping
2022/03/03 06:07:29 INFO  : one: Moved (server-side) to: one.bak
2022/03/03 06:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:07:30 DEBUG : one: md5 = 67f866941f302f2c3d098fd722601fc6 OK
2022/03/03 06:07:30 INFO  : one: Copied (new)
2022/03/03 06:07:30 DEBUG : Waiting for deletions to finish
2022/03/03 06:07:32 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/03/03 06:07:32 INFO  : three.txt: Moved into backup dir
2022/03/03 06:07:34 DEBUG : dst/three.txt: md5 = 7b15498baf7d2bad3076d50a901f2ecf OK
2022/03/03 06:07:35 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/03/03 06:07:35 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:07:35 DEBUG : two: Unchanged skipping
2022/03/03 06:07:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:07:36 INFO  : one.bak: Deleted
2022/03/03 06:07:37 INFO  : one: Moved (server-side) to: one.bak
2022/03/03 06:07:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:07:38 DEBUG : one: md5 = 3b66ac010d915ed88c525f489390a4a1 OK
2022/03/03 06:07:38 INFO  : one: Copied (new)
2022/03/03 06:07:38 DEBUG : Waiting for deletions to finish
2022/03/03 06:07:39 INFO  : three.txt.bak: Deleted
2022/03/03 06:07:40 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/03/03 06:07:40 INFO  : three.txt: Moved into backup dir
2022/03/03 06:07:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:07:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:07:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/03/03 06:07:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/03/03 06:07:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/03/03 06:07:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
--- PASS: TestSyncBackupDirWithSuffix (29.09s)
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:07:48 DEBUG : dst/one: md5 = af58176e38205c376ea034b39ba1e497 OK
2022/03/03 06:07:50 DEBUG : dst/two: md5 = c8c4a72f35e9c554a70179d1eebc54e3 OK
2022/03/03 06:07:51 DEBUG : dst/three.txt: md5 = 2e8ca7d0b12299656d696f0a0ba55d7f OK
2022/03/03 06:07:52 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:07:52 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:07:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/backup"
2022/03/03 06:07:53 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/1nrff024r7pq65ecp72fc28jb0"
2022/03/03 06:07:55 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/03/03 06:07:55 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:07:55 DEBUG : two: Unchanged skipping
2022/03/03 06:07:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:07:57 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/03/03 06:07:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:07:58 DEBUG : one: md5 = 6886328e0c5ed420b89feea0fd49ea4b OK
2022/03/03 06:07:58 INFO  : one: Copied (new)
2022/03/03 06:07:58 DEBUG : Waiting for deletions to finish
2022/03/03 06:07:59 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/03/03 06:07:59 INFO  : three.txt: Moved into backup dir
2022/03/03 06:08:01 DEBUG : dst/three.txt: md5 = 3a5920a1473049bc2e07dd7367e5303c OK
2022/03/03 06:08:02 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:08:02 DEBUG : two: Unchanged skipping
2022/03/03 06:08:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:08:02 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/03/03 06:08:03 INFO  : one-2019-01-01: Deleted
2022/03/03 06:08:04 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/03/03 06:08:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:08:06 DEBUG : one: md5 = 5a00dc0cb51a16ae4b7d1991c489b63c OK
2022/03/03 06:08:06 INFO  : one: Copied (new)
2022/03/03 06:08:06 DEBUG : Waiting for deletions to finish
2022/03/03 06:08:06 INFO  : three-2019-01-01.txt: Deleted
2022/03/03 06:08:07 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/03/03 06:08:07 INFO  : three.txt: Moved into backup dir
2022/03/03 06:08:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:08:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:08:12 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/03/03 06:08:12 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/03/03 06:08:12 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/03/03 06:08:12 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (27.41s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:08:16 DEBUG : dst/one: md5 = 5a45f43f43fcce7815e9dce4a662efd6 OK
2022/03/03 06:08:18 DEBUG : dst/two: md5 = b72d9e800ee4aad3950bebdfd6eb175e OK
2022/03/03 06:08:19 DEBUG : dst/three.txt: md5 = 9e914993c3bde0c8c9fd6b5eaa523df6 OK
2022/03/03 06:08:20 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:08:20 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:08:21 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/03/03 06:08:21 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:08:21 DEBUG : two: Unchanged skipping
2022/03/03 06:08:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:08:22 INFO  : one: Moved (server-side) to: one.bak
2022/03/03 06:08:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:08:23 DEBUG : one: md5 = 4cdf857881a3250af1b27b74d2c265a9 OK
2022/03/03 06:08:23 INFO  : one: Copied (new)
2022/03/03 06:08:23 DEBUG : Waiting for deletions to finish
2022/03/03 06:08:24 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/03/03 06:08:24 INFO  : three.txt: Moved into backup dir
2022/03/03 06:08:26 DEBUG : dst/three.txt: md5 = d07c42a7f9da958b662aa015e4904e2f OK
2022/03/03 06:08:27 DEBUG : one.bak: Excluded from sync (and deletion)
2022/03/03 06:08:27 DEBUG : three.txt.bak: Excluded from sync (and deletion)
2022/03/03 06:08:27 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:08:27 DEBUG : two: Unchanged skipping
2022/03/03 06:08:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for checks to finish
2022/03/03 06:08:27 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/03/03 06:08:28 INFO  : one.bak: Deleted
2022/03/03 06:08:28 INFO  : one: Moved (server-side) to: one.bak
2022/03/03 06:08:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst': Waiting for transfers to finish
2022/03/03 06:08:30 DEBUG : one: md5 = d0808a9e0a3165c9d301038c464bb906 OK
2022/03/03 06:08:30 INFO  : one: Copied (new)
2022/03/03 06:08:30 DEBUG : Waiting for deletions to finish
2022/03/03 06:08:31 INFO  : three.txt.bak: Deleted
2022/03/03 06:08:31 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/03/03 06:08:31 INFO  : three.txt: Moved into backup dir
2022/03/03 06:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/03/03 06:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/03/03 06:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/03/03 06:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
--- PASS: TestSyncBackupDirSuffixOnly (22.76s)
=== RUN   TestSyncSuffix
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:08:38 DEBUG : dst/one: md5 = 6457997c6ec765e4d7ac7d2a2d62b756 OK
2022/03/03 06:08:40 DEBUG : dst/two: md5 = 081d3d0cb6b5991fc6ed875bccdcfda5 OK
2022/03/03 06:08:42 DEBUG : dst/three.txt: md5 = 529f155c8c15084ce182a536aa2bc198 OK
2022/03/03 06:08:42 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:08:42 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:08:43 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/03/03 06:08:44 INFO  : one: Moved (server-side) to: one.bak
2022/03/03 06:08:46 DEBUG : one: md5 = bd6932050493fdc723644baf533de300 OK
2022/03/03 06:08:46 INFO  : one: Copied (new)
2022/03/03 06:08:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:08:46 DEBUG : two: Unchanged skipping
2022/03/03 06:08:46 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2022/03/03 06:08:47 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/03/03 06:08:48 DEBUG : three.txt: md5 = 33a3eba862e5e98358b0b73edf452a6b OK
2022/03/03 06:08:48 INFO  : three.txt: Copied (new)
2022/03/03 06:08:50 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/03/03 06:08:50 INFO  : one.bak: Deleted
2022/03/03 06:08:51 INFO  : one: Moved (server-side) to: one.bak
2022/03/03 06:08:53 DEBUG : one: md5 = 6a3d22579e2074554ecccd7fdad5103b OK
2022/03/03 06:08:53 INFO  : one: Copied (new)
2022/03/03 06:08:53 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:08:53 DEBUG : two: Unchanged skipping
2022/03/03 06:08:53 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2022/03/03 06:08:54 INFO  : three.txt.bak: Deleted
2022/03/03 06:08:55 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/03/03 06:08:56 DEBUG : three.txt: md5 = 05cfcca8cb08c3e3e56c465f087c7d1f OK
2022/03/03 06:08:56 INFO  : three.txt: Copied (new)
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8"
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c"
2022/03/03 06:09:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
--- PASS: TestSyncSuffix (25.62s)
=== RUN   TestSyncSuffixKeepExtension
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:09:04 DEBUG : dst/one: md5 = 5c52c2438358c5aba76d3f8c4cce4890 OK
2022/03/03 06:09:06 DEBUG : dst/two: md5 = 59227e5b17b5934b02a29821bc98be8f OK
2022/03/03 06:09:07 DEBUG : dst/three.txt: md5 = 4e8762007a04629ebd0e9bf7146a59f5 OK
2022/03/03 06:09:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5/dst"
2022/03/03 06:09:08 DEBUG : Creating backend with remote "TestDrive:crypt/30d2bbcsetq11riraf9updndli2lvbt12liabhodfi5rtnql7ofq716mlktjf83pqrlobs1btcfao/31u3jie661vd5p8j7rtc3hgbh0"
2022/03/03 06:09:09 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/03/03 06:09:10 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/03/03 06:09:11 DEBUG : one: md5 = f5a5e4b976df0ac345ecc7a9f5726553 OK
2022/03/03 06:09:11 INFO  : one: Copied (new)
2022/03/03 06:09:11 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:09:11 DEBUG : two: Unchanged skipping
2022/03/03 06:09:12 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2022/03/03 06:09:12 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/03/03 06:09:14 DEBUG : three.txt: md5 = 7670d3a72210f74a7b92e8b9264a67ea OK
2022/03/03 06:09:14 INFO  : three.txt: Copied (new)
2022/03/03 06:09:15 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/03/03 06:09:16 INFO  : one-2019-01-01: Deleted
2022/03/03 06:09:17 INFO  : one: Moved (server-side) to: one-2019-01-01
2022/03/03 06:09:18 DEBUG : one: md5 = fb4ad0c5eb28c0e80bd64724af5697a1 OK
2022/03/03 06:09:18 INFO  : one: Copied (new)
2022/03/03 06:09:18 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:09:18 DEBUG : two: Unchanged skipping
2022/03/03 06:09:19 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2022/03/03 06:09:19 INFO  : three-2019-01-01.txt: Deleted
2022/03/03 06:09:20 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2022/03/03 06:09:21 DEBUG : three.txt: md5 = b78f55de50a17e398f964eff1cfacb3d OK
2022/03/03 06:09:21 INFO  : three.txt: Copied (new)
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc"
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc"
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50"
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k"
2022/03/03 06:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90"
--- PASS: TestSyncSuffixKeepExtension (25.49s)
=== RUN   TestSyncUTFNorm
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:09:29 DEBUG : Testêé: md5 = 6671e6df3cd4afb324e6cca71b21b203 OK
2022/03/03 06:09:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:09:29 DEBUG : Testêé: Sizes differ (src 14 vs dst 18)
2022/03/03 06:09:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:09:30 DEBUG : Testêé: md5 = aeacd00993f1f30d0bb54d8c5ce10b07 OK
2022/03/03 06:09:30 INFO  : Testêé: Copied (replaced existing)
2022/03/03 06:09:30 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncUTFNorm (4.74s)
=== RUN   TestSyncImmutable
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:09:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:09:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:09:34 DEBUG : existing: md5 = 27bc4c1fa7150fc9acf4a78f6a352c4e OK
2022/03/03 06:09:34 INFO  : existing: Copied (new)
2022/03/03 06:09:34 DEBUG : Waiting for deletions to finish
2022/03/03 06:09:35 DEBUG : existing: Sizes differ (src 8 vs dst 6)
2022/03/03 06:09:35 ERROR : existing: Source and destination exist but do not match: immutable file modified
2022/03/03 06:09:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:09:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:09:35 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': not deleting files as there were IO errors
2022/03/03 06:09:35 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': not deleting directories as there were IO errors
--- PASS: TestSyncImmutable (4.67s)
=== RUN   TestSyncIgnoreCase
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:09:38 DEBUG : EXISTING: md5 = 828964440bf164f0b6a511907272dd83 OK
2022/03/03 06:09:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:09:39 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:09:39 DEBUG : existing: Unchanged skipping
2022/03/03 06:09:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:09:39 DEBUG : Waiting for deletions to finish
2022/03/03 06:09:39 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreCase (3.60s)
=== RUN   TestMaxTransfer
=== RUN   TestMaxTransfer/Hard
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", 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-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", 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-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
    sync_test.go:1989: This test only runs on local
--- PASS: TestMaxTransfer (1.47s)
    --- SKIP: TestMaxTransfer/Hard (0.49s)
    --- SKIP: TestMaxTransfer/Soft (0.49s)
    --- SKIP: TestMaxTransfer/Cautious (0.50s)
=== RUN   TestSyncConcurrentDelete
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:09:43 DEBUG : both0: md5 = 0aa32085c3a277bd5257bbdee42d596e OK
2022/03/03 06:09:45 DEBUG : only0: md5 = 357be13a477d7a36ab27c4c960f35b4d OK
2022/03/03 06:09:46 DEBUG : both1: md5 = 781efa839d4f57876ca8345272d088d7 OK
2022/03/03 06:09:48 DEBUG : only1: md5 = eee9f2666f195984c3f2eecd35552197 OK
2022/03/03 06:09:49 DEBUG : both2: md5 = 9bf6472bcbae2665991e146304731e8b OK
2022/03/03 06:09:51 DEBUG : only2: md5 = 45e2cc67a28b7b3c6c60aefa95aa0f56 OK
2022/03/03 06:09:53 DEBUG : both3: md5 = 72883c97ac991f81959d5b55308b4ce0 OK
2022/03/03 06:09:54 DEBUG : only3: md5 = 61ace4ddc67e6b4cb7af3bae5e18aa74 OK
2022/03/03 06:09:56 DEBUG : both4: md5 = 7038ae3ccc21a0f9bcebaf38fdb305e1 OK
2022/03/03 06:09:57 DEBUG : only4: md5 = c9ee3aae3ba8ac828f1076bf9d5222d3 OK
2022/03/03 06:09:59 DEBUG : both5: md5 = ce8bdac539902672c6b1699edca1f9b9 OK
2022/03/03 06:10:00 DEBUG : only5: md5 = 4306b45b4be917c1bedfcf53aebcc895 OK
2022/03/03 06:10:02 DEBUG : both6: md5 = 911e7db1f984c93678a73b90f317b781 OK
2022/03/03 06:10:03 DEBUG : only6: md5 = ffc381e7a7352f3b184bf0453fe46f48 OK
2022/03/03 06:10:05 DEBUG : both7: md5 = f614525ce509e96d61c03960eca035ea OK
2022/03/03 06:10:06 DEBUG : only7: md5 = acee76bf81c99dd49520c2ddb1f19e5a OK
2022/03/03 06:10:08 DEBUG : both8: md5 = f6e09f25cff52a4d220f2388c962b202 OK
2022/03/03 06:10:09 DEBUG : only8: md5 = 0d686bda65c07aedf05b8157eabb06b3 OK
2022/03/03 06:10:11 DEBUG : both9: md5 = 4049f0081175e7082e2567400b6814d3 OK
2022/03/03 06:10:13 DEBUG : only9: md5 = 07f158f4fc174e5be66a7ef154ea60b0 OK
2022/03/03 06:10:14 DEBUG : both10: md5 = 76e8ecf15f8aa4fa8b2435cd878ec99e OK
2022/03/03 06:10:16 DEBUG : only10: md5 = 60f39a95d66c5077ef2e50aa63e83076 OK
2022/03/03 06:10:17 DEBUG : both11: md5 = 5d1567c0cb3c4c63f6807b0c6ac5f707 OK
2022/03/03 06:10:19 DEBUG : only11: md5 = ce73c7a33991273df73ce2d82a6a183c OK
2022/03/03 06:10:20 DEBUG : both12: md5 = a2d83e57a6784d7334f1abab3a74487c OK
2022/03/03 06:10:22 DEBUG : only12: md5 = 87791710d189013e5345ad997a9e43ab OK
2022/03/03 06:10:23 DEBUG : both13: md5 = dbd4f1696d5c264797e7ffa9c6ff9640 OK
2022/03/03 06:10:25 DEBUG : only13: md5 = 1a9904cda85245728649f261dbbdb523 OK
2022/03/03 06:10:26 DEBUG : both14: md5 = 3c90f1c46acf6aa319cbfca85eb1f4bb OK
2022/03/03 06:10:28 DEBUG : only14: md5 = 4931878166b367c7820803e23b70c1db OK
2022/03/03 06:10:29 DEBUG : both15: md5 = b2fcb7602daceefa8ae7644e1c6b33f2 OK
2022/03/03 06:10:31 DEBUG : only15: md5 = 9161b79fc7fa76ee5f03dd21d4a486ca OK
2022/03/03 06:10:33 DEBUG : both16: md5 = a259038318fba974435b81c4f0468795 OK
2022/03/03 06:10:34 DEBUG : only16: md5 = 077bacf504772720b645b0d4eedb55fa OK
2022/03/03 06:10:36 DEBUG : both17: md5 = 15d29f71874c7570e89f1aec4c6b969b OK
2022/03/03 06:10:37 DEBUG : only17: md5 = d55c98aa107784cffb4c4488dcbd36e9 OK
2022/03/03 06:10:39 DEBUG : both18: md5 = a1ddccf9d156ac027c03d9942944e91d OK
2022/03/03 06:10:40 DEBUG : only18: md5 = b3187d1fa061c905b1708020fa1d2e81 OK
2022/03/03 06:10:42 DEBUG : both19: md5 = baf7caa547a6924de5cf5012ff993b45 OK
2022/03/03 06:10:43 DEBUG : only19: md5 = cece0bc7bad88c05dbe054344e578bf1 OK
2022/03/03 06:10:44 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both0: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both1: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both10: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both11: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both12: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both13: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both14: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both15: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both16: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both17: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both18: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both19: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both2: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both3: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both4: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both5: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both6: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both7: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both8: Unchanged skipping
2022/03/03 06:10:44 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:10:44 DEBUG : both9: Unchanged skipping
2022/03/03 06:10:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:10:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:10:44 DEBUG : Waiting for deletions to finish
2022/03/03 06:10:45 INFO  : only11: Deleted
2022/03/03 06:10:45 INFO  : only10: Deleted
2022/03/03 06:10:45 INFO  : only6: Deleted
2022/03/03 06:10:45 INFO  : only4: Deleted
2022/03/03 06:10:45 INFO  : only13: Deleted
2022/03/03 06:10:45 INFO  : only14: Deleted
2022/03/03 06:10:45 INFO  : only15: Deleted
2022/03/03 06:10:46 INFO  : only2: Deleted
2022/03/03 06:10:46 INFO  : only1: Deleted
2022/03/03 06:10:46 INFO  : only12: Deleted
2022/03/03 06:10:46 INFO  : only17: Deleted
2022/03/03 06:10:46 INFO  : only9: Deleted
2022/03/03 06:10:46 INFO  : only0: Deleted
2022/03/03 06:10:47 INFO  : only16: Deleted
2022/03/03 06:10:47 INFO  : only18: Deleted
2022/03/03 06:10:47 INFO  : only7: Deleted
2022/03/03 06:10:47 INFO  : only19: Deleted
2022/03/03 06:10:47 INFO  : only8: Deleted
2022/03/03 06:10:47 INFO  : only3: Deleted
2022/03/03 06:10:47 INFO  : only5: Deleted
2022/03/03 06:10:47 INFO  : There was nothing to transfer
--- PASS: TestSyncConcurrentDelete (77.38s)
=== RUN   TestSyncConcurrentTruncate
    run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5'", Local "Local file system at /tmp/rclone3514476916", Modify Window "1ms"
2022/03/03 06:11:00 DEBUG : both0: md5 = 737988128bd6311f8b14fa87a4f1ecd2 OK
2022/03/03 06:11:02 DEBUG : only0: md5 = ad0cace730763027418c7709a8fdf86b OK
2022/03/03 06:11:03 DEBUG : both1: md5 = 9d2daf39dccccf4a7f518d4a95ba3a1f OK
2022/03/03 06:11:05 DEBUG : only1: md5 = 385c1cf567490fd021348efd2f0f8ffd OK
2022/03/03 06:11:06 DEBUG : both2: md5 = 361240d1cba047c08e048a53bf175ae2 OK
2022/03/03 06:11:08 DEBUG : only2: md5 = eb68a191e5eda3ff9626307d8f503b9f OK
2022/03/03 06:11:09 DEBUG : both3: md5 = 14101c4582c678d28c2771e383787173 OK
2022/03/03 06:11:11 DEBUG : only3: md5 = 6bcb6c617dae7ce7255b2949eeaf3ef6 OK
2022/03/03 06:11:12 DEBUG : both4: md5 = 4e90d845cef003a1351627e175ae62be OK
2022/03/03 06:11:14 DEBUG : only4: md5 = 168564da47d1b4dc24d97d5a1b51bb4e OK
2022/03/03 06:11:15 DEBUG : both5: md5 = 304b4788b15f8696947ba604724a1ee7 OK
2022/03/03 06:11:17 DEBUG : only5: md5 = 2b2e2c5b22710328995f110dfb54b13d OK
2022/03/03 06:11:18 DEBUG : both6: md5 = 5412cf6e21596eb4e9af8229822bb6f6 OK
2022/03/03 06:11:20 DEBUG : only6: md5 = d468d9cf173235e7425213a8f0cca037 OK
2022/03/03 06:11:21 DEBUG : both7: md5 = 2f252f6b7166c9978a700376dea054dc OK
2022/03/03 06:11:23 DEBUG : only7: md5 = 032a6fa654ceab7ef1c05334fa4c1740 OK
2022/03/03 06:11:24 DEBUG : both8: md5 = d9d891e8c150aa803b4e45bd95a03670 OK
2022/03/03 06:11:26 DEBUG : only8: md5 = 2978a8cda4a8fe8c5f3c51b3b07ba20a OK
2022/03/03 06:11:27 DEBUG : both9: md5 = 4cfd0bf26c6db21407087eeb9990b54e OK
2022/03/03 06:11:28 DEBUG : only9: md5 = b888daa731dd7fbc4a6ad8be8673fa27 OK
2022/03/03 06:11:30 DEBUG : both10: md5 = 0d49be3da83ba709ba4fa80db1c18b9d OK
2022/03/03 06:11:32 DEBUG : only10: md5 = 92ee21b541693acdbf0478082c05f9d5 OK
2022/03/03 06:11:33 DEBUG : both11: md5 = 9256bd528edb0ff426944dc3628896f2 OK
2022/03/03 06:11:34 DEBUG : only11: md5 = cab62ff5cc95b47002b2dd76efa4f970 OK
2022/03/03 06:11:36 DEBUG : both12: md5 = 0c50f12fe90e3881d3d7b108102c45e4 OK
2022/03/03 06:11:37 DEBUG : only12: md5 = fc5943820c499676027c4919a565f853 OK
2022/03/03 06:11:39 DEBUG : both13: md5 = aa1f257eaa5480c1ec5c9b42823973dd OK
2022/03/03 06:11:41 DEBUG : only13: md5 = e153b78bd2ef9236a6c579118d67f7f3 OK
2022/03/03 06:11:42 DEBUG : both14: md5 = 753eac81b58e5a49cf59998e0cbb7516 OK
2022/03/03 06:11:44 DEBUG : only14: md5 = 1f3c1ecd10a2ec6706134108da8f164a OK
2022/03/03 06:11:45 DEBUG : both15: md5 = d837d93728adb026b55bfa78c3ae9e98 OK
2022/03/03 06:11:47 DEBUG : only15: md5 = 23531bdf9c560309d971cb4aef6c836c OK
2022/03/03 06:11:48 DEBUG : both16: md5 = d72f69522967e7727e957268b0143dcc OK
2022/03/03 06:11:50 DEBUG : only16: md5 = a9420ce611741838cb8635f890e7f932 OK
2022/03/03 06:11:51 DEBUG : both17: md5 = 02461adadcb6bb6e3ce6c142f50690b9 OK
2022/03/03 06:11:53 DEBUG : only17: md5 = 8e3f90192b43ebe31169d17ca81b8d31 OK
2022/03/03 06:11:54 DEBUG : both18: md5 = da906f98bf43826cd07f22c1f5b9c3df OK
2022/03/03 06:11:56 DEBUG : only18: md5 = f555d2dea4088059c106360f4f570381 OK
2022/03/03 06:11:57 DEBUG : both19: md5 = 2fb624cc506792dcbf48b495329b993f OK
2022/03/03 06:11:59 DEBUG : only19: md5 = 32eb125b6f7963aee764c45da847d97a OK
2022/03/03 06:11:59 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both0: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both10: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both12: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both13: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for checks to finish
2022/03/03 06:11:59 DEBUG : both14: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both11: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both16: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both17: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both18: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both19: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both2: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both3: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both4: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both5: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both6: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both7: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both8: Unchanged skipping
2022/03/03 06:11:59 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both9: Unchanged skipping
2022/03/03 06:11:59 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : both15: Unchanged skipping
2022/03/03 06:11:59 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2022/03/03 06:11:59 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2022/03/03 06:11:59 DEBUG : both1: Unchanged skipping
2022/03/03 06:11:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Waiting for transfers to finish
2022/03/03 06:12:01 DEBUG : only10: md5 = e33cc637b6d84b42763ec3a7fb97d0be OK
2022/03/03 06:12:01 INFO  : only10: Copied (replaced existing)
2022/03/03 06:12:01 DEBUG : only0: md5 = dab332f8c73e4e17fb8232ec337f78c9 OK
2022/03/03 06:12:01 INFO  : only0: Copied (replaced existing)
2022/03/03 06:12:01 DEBUG : only1: md5 = b06347dcf37a6ae90e7abdae5febf6ed OK
2022/03/03 06:12:01 INFO  : only1: Copied (replaced existing)
2022/03/03 06:12:01 DEBUG : only12: md5 = f590b277a672e04293d4f13736df408f OK
2022/03/03 06:12:01 INFO  : only12: Copied (replaced existing)
2022/03/03 06:12:02 DEBUG : only14: md5 = e9c8c90be4b175df8a5d2782e24da154 OK
2022/03/03 06:12:02 INFO  : only14: Copied (replaced existing)
2022/03/03 06:12:02 DEBUG : only15: md5 = 124fa023333196a8b810b6aa35d432f9 OK
2022/03/03 06:12:02 INFO  : only15: Copied (replaced existing)
2022/03/03 06:12:02 DEBUG : only16: md5 = d0ff75e0904997959e377a7eeec6ad0f OK
2022/03/03 06:12:02 INFO  : only16: Copied (replaced existing)
2022/03/03 06:12:02 DEBUG : only17: md5 = ee0beb9a1989d2bad6dae40bf7b7c251 OK
2022/03/03 06:12:02 INFO  : only17: Copied (replaced existing)
2022/03/03 06:12:03 DEBUG : only18: md5 = 5ede33586089ed3eb43ea99891478398 OK
2022/03/03 06:12:03 INFO  : only18: Copied (replaced existing)
2022/03/03 06:12:03 DEBUG : only19: md5 = b84498fe3c2b5509693aad4ee6d7ca16 OK
2022/03/03 06:12:03 INFO  : only19: Copied (replaced existing)
2022/03/03 06:12:03 DEBUG : only2: md5 = 6b34caf3e65d9c437aba61b8737a05d5 OK
2022/03/03 06:12:03 INFO  : only2: Copied (replaced existing)
2022/03/03 06:12:03 DEBUG : only3: md5 = 44e1bd7a76c00e21226f1dc8f064938b OK
2022/03/03 06:12:03 INFO  : only3: Copied (replaced existing)
2022/03/03 06:12:04 DEBUG : only4: md5 = d258d3cb44aaaeba58bbd1df3116fb63 OK
2022/03/03 06:12:04 INFO  : only4: Copied (replaced existing)
2022/03/03 06:12:04 DEBUG : only6: md5 = f0d465cbbd208717824cc76032935041 OK
2022/03/03 06:12:04 INFO  : only6: Copied (replaced existing)
2022/03/03 06:12:05 DEBUG : only5: md5 = 025aa18efaecdfa34c3184128ec5dcc1 OK
2022/03/03 06:12:05 INFO  : only5: Copied (replaced existing)
2022/03/03 06:12:05 DEBUG : only7: md5 = 68847916040806afaa941177f8681a44 OK
2022/03/03 06:12:05 INFO  : only7: Copied (replaced existing)
2022/03/03 06:12:06 DEBUG : only8: md5 = e86ff5730b6d35eed6741d88fbbd111d OK
2022/03/03 06:12:06 INFO  : only8: Copied (replaced existing)
2022/03/03 06:12:06 DEBUG : only9: md5 = d03ecfb80ac58bf7b85e2ce549f07e1d OK
2022/03/03 06:12:06 INFO  : only9: Copied (replaced existing)
2022/03/03 06:12:06 DEBUG : only13: md5 = 98c6d08b6e18be339f91a3faa47c5719 OK
2022/03/03 06:12:06 INFO  : only13: Copied (replaced existing)
2022/03/03 06:12:06 DEBUG : only11: md5 = de609bdc2cf83a8b4bba787c650dd0da OK
2022/03/03 06:12:06 INFO  : only11: Copied (replaced existing)
2022/03/03 06:12:06 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncConcurrentTruncate (89.68s)
PASS
2022/03/03 06:12:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cugozul3toqopiy0semimap5': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 13m21.15681449s (try 1/5)