"./operations.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bBox: -verbose -size-limit 1024" - Starting (try 1/5)
2025/02/07 02:21:05 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo"
2025/02/07 02:21:05 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:21:05 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo"
2025/02/07 02:21:08 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:21:08 DEBUG : Reset feature "ListR"
2025/02/07 02:21:08 DEBUG : Creating backend with remote "/tmp/rclone1667611889"
=== RUN   TestDoMultiThreadCopy
--- PASS: TestDoMultiThreadCopy (0.00s)
=== RUN   TestMultithreadCalculateNumChunks
=== RUN   TestMultithreadCalculateNumChunks/{size:1_chunkSize:65536_wantNumChunks:1}
=== RUN   TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:1_wantNumChunks:1048576}
=== RUN   TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:2_wantNumChunks:524288}
=== RUN   TestMultithreadCalculateNumChunks/{size:1048577_chunkSize:2_wantNumChunks:524289}
=== RUN   TestMultithreadCalculateNumChunks/{size:1048575_chunkSize:2_wantNumChunks:524288}
--- PASS: TestMultithreadCalculateNumChunks (0.00s)
    --- PASS: TestMultithreadCalculateNumChunks/{size:1_chunkSize:65536_wantNumChunks:1} (0.00s)
    --- PASS: TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:1_wantNumChunks:1048576} (0.00s)
    --- PASS: TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:2_wantNumChunks:524288} (0.00s)
    --- PASS: TestMultithreadCalculateNumChunks/{size:1048577_chunkSize:2_wantNumChunks:524289} (0.00s)
    --- PASS: TestMultithreadCalculateNumChunks/{size:1048575_chunkSize:2_wantNumChunks:524288} (0.00s)
=== RUN   TestMultithreadCopy
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    multithread_test.go:121: multithread writing not supported
2025/02/07 02:21:09 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:21:09 ERROR : : error listing: directory not found
--- SKIP: TestMultithreadCopy (0.72s)
=== RUN   TestMultithreadCopyAbort
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    multithread_test.go:121: multithread writing not supported
2025/02/07 02:21:12 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:21:12 ERROR : : error listing: directory not found
--- SKIP: TestMultithreadCopyAbort (3.31s)
=== RUN   TestSizeDiffers
--- PASS: TestSizeDiffers (0.00s)
=== RUN   TestReOpen
=== RUN   TestReOpen/Normal
=== RUN   TestReOpen/Normal/Basics
2025/02/07 02:21:12 DEBUG : potato: Seek from 10 to 0
=== RUN   TestReOpen/Normal/ErrorAtStart
=== RUN   TestReOpen/Normal/WithErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error
=== RUN   TestReOpen/Normal/TooManyErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries
=== RUN   TestReOpen/Normal/Seek
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Seek from 5 to 2
=== RUN   TestReOpen/Normal/AccountRead
=== RUN   TestReOpen/Normal/AccountReadDelay
2025/02/07 02:21:12 DEBUG : potato: Seek from 10 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 10 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 10 to 0
=== RUN   TestReOpen/Normal/AccountReadError
=== RUN   TestReOpen/WithRangeOption
=== RUN   TestReOpen/WithRangeOption/Basics
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 0
=== RUN   TestReOpen/WithRangeOption/ErrorAtStart
=== RUN   TestReOpen/WithRangeOption/WithErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error
=== RUN   TestReOpen/WithRangeOption/TooManyErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries
=== RUN   TestReOpen/WithRangeOption/Seek
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Seek from 5 to 2
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 4
=== RUN   TestReOpen/WithRangeOption/AccountRead
=== RUN   TestReOpen/WithRangeOption/AccountReadDelay
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 0
=== RUN   TestReOpen/WithRangeOption/AccountReadError
=== RUN   TestReOpen/WithSeekOption
=== RUN   TestReOpen/WithSeekOption/Basics
2025/02/07 02:21:12 DEBUG : potato: Seek from 8 to 0
=== RUN   TestReOpen/WithSeekOption/ErrorAtStart
=== RUN   TestReOpen/WithSeekOption/WithErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error
=== RUN   TestReOpen/WithSeekOption/TooManyErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries
=== RUN   TestReOpen/WithSeekOption/Seek
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Seek from 5 to 2
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 5
=== RUN   TestReOpen/WithSeekOption/AccountRead
=== RUN   TestReOpen/WithSeekOption/AccountReadDelay
2025/02/07 02:21:12 DEBUG : potato: Seek from 8 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 8 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 8 to 0
=== RUN   TestReOpen/WithSeekOption/AccountReadError
=== RUN   TestReOpen/UnknownSize
=== RUN   TestReOpen/UnknownSize/Basics
2025/02/07 02:21:12 DEBUG : potato: Seek from 9 to 0
=== RUN   TestReOpen/UnknownSize/ErrorAtStart
=== RUN   TestReOpen/UnknownSize/WithErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error
=== RUN   TestReOpen/UnknownSize/TooManyErrors
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error
2025/02/07 02:21:12 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries
=== RUN   TestReOpen/UnknownSize/Seek
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error
2025/02/07 02:21:12 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error
2025/02/07 02:21:12 DEBUG : potato: Seek from 5 to 2
2025/02/07 02:21:12 DEBUG : potato: Seek from 7 to 6
=== RUN   TestReOpen/UnknownSize/AccountRead
=== RUN   TestReOpen/UnknownSize/AccountReadDelay
2025/02/07 02:21:12 DEBUG : potato: Seek from 9 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 9 to 0
2025/02/07 02:21:12 DEBUG : potato: Seek from 9 to 0
=== RUN   TestReOpen/UnknownSize/AccountReadError
--- PASS: TestReOpen (0.00s)
    --- PASS: TestReOpen/Normal (0.00s)
        --- PASS: TestReOpen/Normal/Basics (0.00s)
        --- PASS: TestReOpen/Normal/ErrorAtStart (0.00s)
        --- PASS: TestReOpen/Normal/WithErrors (0.00s)
        --- PASS: TestReOpen/Normal/TooManyErrors (0.00s)
        --- PASS: TestReOpen/Normal/Seek (0.00s)
        --- PASS: TestReOpen/Normal/AccountRead (0.00s)
        --- PASS: TestReOpen/Normal/AccountReadDelay (0.00s)
        --- PASS: TestReOpen/Normal/AccountReadError (0.00s)
    --- PASS: TestReOpen/WithRangeOption (0.00s)
        --- PASS: TestReOpen/WithRangeOption/Basics (0.00s)
        --- PASS: TestReOpen/WithRangeOption/ErrorAtStart (0.00s)
        --- PASS: TestReOpen/WithRangeOption/WithErrors (0.00s)
        --- PASS: TestReOpen/WithRangeOption/TooManyErrors (0.00s)
        --- PASS: TestReOpen/WithRangeOption/Seek (0.00s)
        --- PASS: TestReOpen/WithRangeOption/AccountRead (0.00s)
        --- PASS: TestReOpen/WithRangeOption/AccountReadDelay (0.00s)
        --- PASS: TestReOpen/WithRangeOption/AccountReadError (0.00s)
    --- PASS: TestReOpen/WithSeekOption (0.00s)
        --- PASS: TestReOpen/WithSeekOption/Basics (0.00s)
        --- PASS: TestReOpen/WithSeekOption/ErrorAtStart (0.00s)
        --- PASS: TestReOpen/WithSeekOption/WithErrors (0.00s)
        --- PASS: TestReOpen/WithSeekOption/TooManyErrors (0.00s)
        --- PASS: TestReOpen/WithSeekOption/Seek (0.00s)
        --- PASS: TestReOpen/WithSeekOption/AccountRead (0.00s)
        --- PASS: TestReOpen/WithSeekOption/AccountReadDelay (0.00s)
        --- PASS: TestReOpen/WithSeekOption/AccountReadError (0.00s)
    --- PASS: TestReOpen/UnknownSize (0.00s)
        --- PASS: TestReOpen/UnknownSize/Basics (0.00s)
        --- PASS: TestReOpen/UnknownSize/ErrorAtStart (0.00s)
        --- PASS: TestReOpen/UnknownSize/WithErrors (0.00s)
        --- PASS: TestReOpen/UnknownSize/TooManyErrors (0.00s)
        --- PASS: TestReOpen/UnknownSize/Seek (0.00s)
        --- PASS: TestReOpen/UnknownSize/AccountRead (0.00s)
        --- PASS: TestReOpen/UnknownSize/AccountReadDelay (0.00s)
        --- PASS: TestReOpen/UnknownSize/AccountReadError (0.00s)
=== RUN   TestCheck
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:21:15 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:21:30 INFO  : rutabaga.rclone_chunk.001_apgqxx: Moved (server-side) to: rutabaga
=== RUN   TestCheck/1
=== RUN   TestCheck/2
2025/02/07 02:21:37 INFO  : empty space.rclone_chunk.001_aph580: Moved (server-side) to: empty space
=== RUN   TestCheck/3
2025/02/07 02:21:49 INFO  : potato2.rclone_chunk.001_aphb00: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 02:21:51 INFO  : potato2.rclone_chunk.002_aphb00: Moved (server-side) to: potato2.rclone_chunk.002
=== RUN   TestCheck/4
=== RUN   TestCheck/5
2025/02/07 02:22:08 INFO  : remotepotato.rclone_chunk.001_aphxwf: Moved (server-side) to: remotepotato.rclone_chunk.001
2025/02/07 02:22:09 INFO  : remotepotato.rclone_chunk.002_aphxwf: Moved (server-side) to: remotepotato.rclone_chunk.002
=== RUN   TestCheck/6
=== RUN   TestCheck/7
--- PASS: TestCheck (79.80s)
    --- PASS: TestCheck/1 (0.67s)
    --- PASS: TestCheck/2 (0.43s)
    --- PASS: TestCheck/3 (0.37s)
    --- PASS: TestCheck/4 (1.15s)
    --- PASS: TestCheck/5 (0.41s)
    --- PASS: TestCheck/6 (0.39s)
    --- PASS: TestCheck/7 (1.11s)
=== RUN   TestCheckFsError
2025/02/07 02:22:32 DEBUG : Creating backend with remote "nonexistent"
2025/02/07 02:22:32 DEBUG : Config file has changed externally - reloading
2025/02/07 02:22:32 DEBUG : Creating backend with remote "nonexistent"
2025/02/07 02:22:32 DEBUG : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: Waiting for checks to finish
2025/02/07 02:22:32 ERROR : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: error reading source root directory: directory not found
2025/02/07 02:22:32 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: 2 differences found
2025/02/07 02:22:32 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: 2 errors while checking
--- PASS: TestCheckFsError (0.00s)
=== RUN   TestCheckDownload
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:22:37 INFO  : rutabaga.rclone_chunk.001_apiuax: Moved (server-side) to: rutabaga
=== RUN   TestCheckDownload/1
=== RUN   TestCheckDownload/2
2025/02/07 02:22:46 INFO  : empty space.rclone_chunk.001_apj2ta: Moved (server-side) to: empty space
=== RUN   TestCheckDownload/3
2025/02/07 02:22:55 INFO  : potato2.rclone_chunk.001_apj97e: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 02:22:56 INFO  : potato2.rclone_chunk.002_apj97e: Moved (server-side) to: potato2.rclone_chunk.002
=== RUN   TestCheckDownload/4
=== RUN   TestCheckDownload/5
2025/02/07 02:23:37 INFO  : remotepotato.rclone_chunk.001_apjtst: Moved (server-side) to: remotepotato.rclone_chunk.001
2025/02/07 02:23:38 INFO  : remotepotato.rclone_chunk.002_apjtst: Moved (server-side) to: remotepotato.rclone_chunk.002
=== RUN   TestCheckDownload/6
=== RUN   TestCheckDownload/7
--- PASS: TestCheckDownload (92.25s)
    --- PASS: TestCheckDownload/1 (1.84s)
    --- PASS: TestCheckDownload/2 (1.06s)
    --- PASS: TestCheckDownload/3 (1.66s)
    --- PASS: TestCheckDownload/4 (3.89s)
    --- PASS: TestCheckDownload/5 (4.10s)
    --- PASS: TestCheckDownload/6 (3.96s)
    --- PASS: TestCheckDownload/7 (3.76s)
=== RUN   TestCheckSizeOnly
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:24:09 INFO  : rutabaga.rclone_chunk.001_aplew3: Moved (server-side) to: rutabaga
=== RUN   TestCheckSizeOnly/1
=== RUN   TestCheckSizeOnly/2
2025/02/07 02:24:16 INFO  : empty space.rclone_chunk.001_apllrw: Moved (server-side) to: empty space
=== RUN   TestCheckSizeOnly/3
2025/02/07 02:24:24 INFO  : potato2.rclone_chunk.001_aplr0m: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 02:24:25 INFO  : potato2.rclone_chunk.002_aplr0m: Moved (server-side) to: potato2.rclone_chunk.002
=== RUN   TestCheckSizeOnly/4
=== RUN   TestCheckSizeOnly/5
2025/02/07 02:24:36 INFO  : remotepotato.rclone_chunk.001_apm2v1: Moved (server-side) to: remotepotato.rclone_chunk.001
2025/02/07 02:24:37 INFO  : remotepotato.rclone_chunk.002_apm2v1: Moved (server-side) to: remotepotato.rclone_chunk.002
=== RUN   TestCheckSizeOnly/6
=== RUN   TestCheckSizeOnly/7
--- PASS: TestCheckSizeOnly (52.87s)
    --- PASS: TestCheckSizeOnly/1 (0.56s)
    --- PASS: TestCheckSizeOnly/2 (0.56s)
    --- PASS: TestCheckSizeOnly/3 (0.55s)
    --- PASS: TestCheckSizeOnly/4 (0.59s)
    --- PASS: TestCheckSizeOnly/5 (0.57s)
    --- PASS: TestCheckSizeOnly/6 (0.57s)
    --- PASS: TestCheckSizeOnly/7 (0.62s)
=== RUN   TestCheckEqualReaders
--- PASS: TestCheckEqualReaders (0.00s)
=== RUN   TestParseSumFile
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:25:06 INFO  : test.sum.rclone_chunk.001_apmv43: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:25:07 INFO  : test.sum.rclone_chunk.002_apmv43: Moved (server-side) to: test.sum.rclone_chunk.002
2025/02/07 02:25:16 NOTICE: test.sum: improperly formatted checksum line 4
2025/02/07 02:25:16 NOTICE: test.sum: improperly formatted checksum line 5
2025/02/07 02:25:16 NOTICE: test.sum: improperly formatted checksum line 6
2025/02/07 02:25:16 NOTICE: test.sum: 2 warning(s) suppressed...
2025/02/07 02:25:30 INFO  : test.sum.rclone_chunk.001_apng04: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:25:31 INFO  : test.sum.rclone_chunk.002_apng04: Moved (server-side) to: test.sum.rclone_chunk.002
2025/02/07 02:25:38 NOTICE: test.sum: improperly formatted checksum line 4
2025/02/07 02:25:38 NOTICE: test.sum: improperly formatted checksum line 5
2025/02/07 02:25:38 NOTICE: test.sum: improperly formatted checksum line 6
2025/02/07 02:25:38 NOTICE: test.sum: 2 warning(s) suppressed...
--- PASS: TestParseSumFile (47.22s)
=== RUN   TestCheckSum
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:25:44 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/data"
2025/02/07 02:25:44 DEBUG : Config file has changed externally - reloading
2025/02/07 02:25:44 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/data"
2025/02/07 02:25:50 DEBUG : Reset feature "ListR"
    check_test.go:353: Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo/data' lacks md5, skipping
--- SKIP: TestCheckSum (6.96s)
=== RUN   TestCheckSumDownload
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:25:51 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/data"
2025/02/07 02:25:51 DEBUG : Config file has changed externally - reloading
2025/02/07 02:25:51 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/data"
2025/02/07 02:25:59 DEBUG : Reset feature "ListR"
2025/02/07 02:26:10 INFO  : data/banana.rclone_chunk.001_apolih: Moved (server-side) to: data/banana
2025/02/07 02:26:16 INFO  : test.sum.rclone_chunk.001_apowut: Moved (server-side) to: test.sum
=== RUN   TestCheckSumDownload/subtest1
2025/02/07 02:26:33 INFO  : data/potato.rclone_chunk.001_appa9s: Moved (server-side) to: data/potato
2025/02/07 02:26:42 INFO  : test.sum: Deleted
2025/02/07 02:26:43 INFO  : test.sum.rclone_chunk.001_appkjb: Moved (server-side) to: test.sum
=== RUN   TestCheckSumDownload/subtest2
2025/02/07 02:27:06 INFO  : test.sum.rclone_chunk.001_apq8n6: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:27:07 INFO  : test.sum.rclone_chunk.002_apq8n6: Moved (server-side) to: test.sum.rclone_chunk.002
=== RUN   TestCheckSumDownload/subtest3
2025/02/07 02:27:38 INFO  : test.sum.rclone_chunk.001_apqz98: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:27:38 INFO  : test.sum.rclone_chunk.002_apqz98: Moved (server-side) to: test.sum.rclone_chunk.002
=== RUN   TestCheckSumDownload/subtest4
2025/02/07 02:28:19 INFO  : test.sum.rclone_chunk.001_aprtui: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:28:22 INFO  : test.sum.rclone_chunk.002_aprtui: Moved (server-side) to: test.sum.rclone_chunk.002
2025/02/07 02:28:24 INFO  : test.sum.rclone_chunk.003_aprtui: Moved (server-side) to: test.sum.rclone_chunk.003
=== RUN   TestCheckSumDownload/subtest5
2025/02/07 02:29:02 INFO  : test.sum.rclone_chunk.001_apsz2l: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:29:12 INFO  : test.sum.rclone_chunk.002_apsz2l: Moved (server-side) to: test.sum.rclone_chunk.002
2025/02/07 02:29:15 INFO  : test.sum.rclone_chunk.003_apsz2l: Moved (server-side) to: test.sum.rclone_chunk.003
=== RUN   TestCheckSumDownload/subtest6
2025/02/07 02:29:29 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:29:29 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:29:29 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:29:29 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:29:30 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:29:32 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:29:32 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:29:32 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:29:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:29:33 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:29:41 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:29:41 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:29:44 INFO  : data/banana: Deleted
2025/02/07 02:29:45 INFO  : data/banana.rclone_chunk.001_apuei8: Moved (server-side) to: data/banana
2025/02/07 02:29:58 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:29:58 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:29:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:30:15 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:30:16 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:30:16 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:30:18 INFO  : data/potato: Deleted
2025/02/07 02:30:19 INFO  : data/potato.rclone_chunk.001_apuv0k: Moved (server-side) to: data/potato
2025/02/07 02:30:49 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:30:49 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:30:49 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:30:49 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:30:49 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:30:49 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:30:49 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:30:51 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:30:53 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:30:55 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:30:56 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:30:56 INFO  : test.sum.rclone_chunk.001_apvya2: Moved (server-side) to: test.sum.rclone_chunk.001
2025/02/07 02:31:04 INFO  : test.sum.rclone_chunk.002_apvya2: Moved (server-side) to: test.sum.rclone_chunk.002
=== RUN   TestCheckSumDownload/subtest7
2025/02/07 02:31:25 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:31:32 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:31:38 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:31:38 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:31:38 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:31:39 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:31:40 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:31:40 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:31:40 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:31:41 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:31:42 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:31:47 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:31:49 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:31:51 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:31:51 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:31:51 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:31:52 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:31:52 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:31:52 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:31:52 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:31:52 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:31:52 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/02/07 02:31:57 DEBUG : pacer: Reducing sleep to 60ms
--- PASS: TestCheckSumDownload (365.90s)
    --- PASS: TestCheckSumDownload/subtest1 (7.35s)
    --- PASS: TestCheckSumDownload/subtest2 (9.61s)
    --- PASS: TestCheckSumDownload/subtest3 (9.65s)
    --- PASS: TestCheckSumDownload/subtest4 (11.38s)
    --- PASS: TestCheckSumDownload/subtest5 (7.30s)
    --- PASS: TestCheckSumDownload/subtest6 (8.04s)
    --- PASS: TestCheckSumDownload/subtest7 (12.46s)
=== RUN   TestApplyTransforms
2025/02/07 02:31:57 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-loqexuz9heki"
2025/02/07 02:31:57 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:31:57 DEBUG : Creating backend with remote "TestBox:rclone-test-loqexuz9heki"
2025/02/07 02:32:00 DEBUG : box root 'rclone-test-loqexuz9heki': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:32:00 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:00 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:00 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:32:01 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:01 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:01 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:32:01 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:01 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:01 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/02/07 02:32:01 DEBUG : pacer: Reducing sleep to 60ms
2025/02/07 02:32:01 DEBUG : Reset feature "ListR"
2025/02/07 02:32:01 DEBUG : Creating backend with remote "/tmp/rclone3075049606"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki'", Local "Local file system at /tmp/rclone3075049606", Modify Window "1s"
2025/02/07 02:32:01 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:01 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:01 DEBUG : pacer: Rate limited, increasing sleep to 120ms
2025/02/07 02:32:06 DEBUG : pacer: Reducing sleep to 90ms
2025/02/07 02:32:06 DEBUG : box root 'rclone-test-loqexuz9heki': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:32:07 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:07 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:07 DEBUG : pacer: Rate limited, increasing sleep to 180ms
2025/02/07 02:32:10 DEBUG : pacer: Reducing sleep to 135ms
2025/02/07 02:32:15 DEBUG : pacer: Reducing sleep to 101.25ms
2025/02/07 02:32:20 DEBUG : pacer: Reducing sleep to 75.9375ms
2025/02/07 02:32:20 DEBUG : pacer: Reducing sleep to 56.953125ms
2025/02/07 02:32:22 DEBUG : pacer: Reducing sleep to 42.714843ms
2025/02/07 02:32:23 DEBUG : pacer: Reducing sleep to 32.036132ms
2025/02/07 02:32:23 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:23 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:23 DEBUG : pacer: Rate limited, increasing sleep to 64.072264ms
2025/02/07 02:32:24 DEBUG : pacer: Reducing sleep to 48.054198ms
2025/02/07 02:32:25 DEBUG : pacer: Reducing sleep to 36.040648ms
2025/02/07 02:32:25 INFO  : hello, world!.rclone_chunk.001_apz0pn: Moved (server-side) to: hello, world!
2025/02/07 02:32:27 DEBUG : pacer: Reducing sleep to 27.030486ms
upper checkfile vs. lower remote (without normalization)
2025/02/07 02:32:27 DEBUG : pacer: Reducing sleep to 20.272864ms
2025/02/07 02:32:27 ERROR : hello, world!: sum not found
2025/02/07 02:32:27 ERROR : HELLO, WORLD!: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki'
2025/02/07 02:32:27 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki': 1 files missing
2025/02/07 02:32:27 NOTICE: 1 hashes missing
2025/02/07 02:32:27 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki': 2 differences found
2025/02/07 02:32:27 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki': 2 errors while checking
upper checkfile vs. lower remote (with normalization)
2025/02/07 02:32:28 DEBUG : pacer: Reducing sleep to 15.204648ms
2025/02/07 02:32:28 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:28 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:28 DEBUG : pacer: Rate limited, increasing sleep to 30.409296ms
2025/02/07 02:32:29 DEBUG : pacer: Reducing sleep to 22.806972ms
2025/02/07 02:32:29 DEBUG : hello, world!: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:32:29 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki': 0 differences found
2025/02/07 02:32:29 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki': 1 matching files
2025/02/07 02:32:29 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-wabawag2nijo"
2025/02/07 02:32:29 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:32:29 DEBUG : Creating backend with remote "TestBox:rclone-test-wabawag2nijo"
2025/02/07 02:32:30 DEBUG : box root 'rclone-test-wabawag2nijo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:32:31 DEBUG : Reset feature "ListR"
2025/02/07 02:32:31 DEBUG : Creating backend with remote "/tmp/rclone2677805947"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo'", Local "Local file system at /tmp/rclone2677805947", Modify Window "1s"
2025/02/07 02:32:31 DEBUG : box root 'rclone-test-wabawag2nijo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:32:40 INFO  : HELLO, WORLD!.rclone_chunk.001_apzi4o: Moved (server-side) to: HELLO, WORLD!
lower checkfile vs. upper remote (without normalization)
2025/02/07 02:32:43 ERROR : HELLO, WORLD!: sum not found
2025/02/07 02:32:43 ERROR : hello, world!: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo'
2025/02/07 02:32:43 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo': 1 files missing
2025/02/07 02:32:43 NOTICE: 1 hashes missing
2025/02/07 02:32:43 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo': 2 differences found
2025/02/07 02:32:43 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo': 2 errors while checking
lower checkfile vs. upper remote (with normalization)
2025/02/07 02:32:44 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:32:44 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:32:44 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:32:46 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:32:46 DEBUG : HELLO, WORLD!: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:32:46 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo': 0 differences found
2025/02/07 02:32:46 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo': 1 matching files
2025/02/07 02:32:46 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-coyefon9peqo"
2025/02/07 02:32:46 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:32:46 DEBUG : Creating backend with remote "TestBox:rclone-test-coyefon9peqo"
2025/02/07 02:32:47 DEBUG : box root 'rclone-test-coyefon9peqo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:32:48 DEBUG : Reset feature "ListR"
2025/02/07 02:32:48 DEBUG : Creating backend with remote "/tmp/rclone2664919472"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo'", Local "Local file system at /tmp/rclone2664919472", Modify Window "1s"
2025/02/07 02:32:48 DEBUG : box root 'rclone-test-coyefon9peqo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:33:01 INFO  : HeLlO, wOrLd!.rclone_chunk.001_aq0535: Moved (server-side) to: HeLlO, wOrLd!
lower checkfile vs. upperlowermixed remote (without normalization)
2025/02/07 02:33:03 ERROR : HeLlO, wOrLd!: sum not found
2025/02/07 02:33:03 ERROR : hello, world!: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo'
2025/02/07 02:33:03 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo': 1 files missing
2025/02/07 02:33:03 NOTICE: 1 hashes missing
2025/02/07 02:33:03 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo': 2 differences found
2025/02/07 02:33:03 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo': 2 errors while checking
lower checkfile vs. upperlowermixed remote (with normalization)
2025/02/07 02:33:08 DEBUG : HeLlO, wOrLd!: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:33:08 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo': 0 differences found
2025/02/07 02:33:08 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo': 1 matching files
2025/02/07 02:33:08 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-gamuyos8giha"
2025/02/07 02:33:08 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:33:08 DEBUG : Creating backend with remote "TestBox:rclone-test-gamuyos8giha"
2025/02/07 02:33:09 DEBUG : box root 'rclone-test-gamuyos8giha': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:33:10 DEBUG : Reset feature "ListR"
2025/02/07 02:33:10 DEBUG : Creating backend with remote "/tmp/rclone123183515"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha'", Local "Local file system at /tmp/rclone123183515", Modify Window "1s"
2025/02/07 02:33:11 DEBUG : box root 'rclone-test-gamuyos8giha': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:33:32 INFO  : HELLO, WORLD!.rclone_chunk.001_aq0p3l: Moved (server-side) to: HELLO, WORLD!
upperlowermixed checkfile vs. upper remote (without normalization)
2025/02/07 02:33:33 ERROR : HELLO, WORLD!: sum not found
2025/02/07 02:33:33 ERROR : HeLlO, wOrLd!: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha'
2025/02/07 02:33:33 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha': 1 files missing
2025/02/07 02:33:33 NOTICE: 1 hashes missing
2025/02/07 02:33:33 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha': 2 differences found
2025/02/07 02:33:33 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha': 2 errors while checking
upperlowermixed checkfile vs. upper remote (with normalization)
2025/02/07 02:33:36 DEBUG : HELLO, WORLD!: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:33:36 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha': 0 differences found
2025/02/07 02:33:36 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha': 1 matching files
2025/02/07 02:33:36 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-roqufec9dizu"
2025/02/07 02:33:36 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:33:36 DEBUG : Creating backend with remote "TestBox:rclone-test-roqufec9dizu"
2025/02/07 02:33:37 DEBUG : box root 'rclone-test-roqufec9dizu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:33:37 DEBUG : Reset feature "ListR"
2025/02/07 02:33:37 DEBUG : Creating backend with remote "/tmp/rclone1436320750"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu'", Local "Local file system at /tmp/rclone1436320750", Modify Window "1s"
2025/02/07 02:33:40 DEBUG : box root 'rclone-test-roqufec9dizu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:34:02 INFO  : 測試_Русский___ě_áñ.rclone_chunk.001_aq1fn0: Moved (server-side) to: 測試_Русский___ě_áñ
NFD checkfile vs. NFC remote (without normalization)
2025/02/07 02:34:04 ERROR : 測試_Русский___ě_áñ: sum not found
2025/02/07 02:34:04 ERROR : 測試_Русский___ě_áñ: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu'
2025/02/07 02:34:04 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu': 1 files missing
2025/02/07 02:34:04 NOTICE: 1 hashes missing
2025/02/07 02:34:04 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu': 2 differences found
2025/02/07 02:34:04 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu': 2 errors while checking
NFD checkfile vs. NFC remote (with normalization)
2025/02/07 02:34:09 DEBUG : 測試_Русский___ě_áñ: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:34:09 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu': 0 differences found
2025/02/07 02:34:09 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu': 1 matching files
2025/02/07 02:34:09 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-poheyot4quca"
2025/02/07 02:34:09 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:34:09 DEBUG : Creating backend with remote "TestBox:rclone-test-poheyot4quca"
2025/02/07 02:34:13 DEBUG : box root 'rclone-test-poheyot4quca': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:34:16 DEBUG : Reset feature "ListR"
2025/02/07 02:34:16 DEBUG : Creating backend with remote "/tmp/rclone3387587658"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca'", Local "Local file system at /tmp/rclone3387587658", Modify Window "1s"
2025/02/07 02:34:17 DEBUG : box root 'rclone-test-poheyot4quca': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:34:44 INFO  : 測試_Русский___ě_áñ.rclone_chunk.001_aq2hg8: Moved (server-side) to: 測試_Русский___ě_áñ
NFC checkfile vs. NFD remote (without normalization)
2025/02/07 02:34:45 ERROR : 測試_Русский___ě_áñ: sum not found
2025/02/07 02:34:45 ERROR : 測試_Русский___ě_áñ: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca'
2025/02/07 02:34:45 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca': 1 files missing
2025/02/07 02:34:45 NOTICE: 1 hashes missing
2025/02/07 02:34:45 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca': 2 differences found
2025/02/07 02:34:45 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca': 2 errors while checking
NFC checkfile vs. NFD remote (with normalization)
2025/02/07 02:34:52 DEBUG : 測試_Русский___ě_áñ: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:34:52 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca': 0 differences found
2025/02/07 02:34:52 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca': 1 matching files
2025/02/07 02:34:52 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-wegetof5xali"
2025/02/07 02:34:52 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:34:52 DEBUG : Creating backend with remote "TestBox:rclone-test-wegetof5xali"
2025/02/07 02:34:53 DEBUG : box root 'rclone-test-wegetof5xali': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:34:54 DEBUG : Reset feature "ListR"
2025/02/07 02:34:54 DEBUG : Creating backend with remote "/tmp/rclone3399789026"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali'", Local "Local file system at /tmp/rclone3399789026", Modify Window "1s"
2025/02/07 02:34:55 DEBUG : box root 'rclone-test-wegetof5xali': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:35:11 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:35:11 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:35:11 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:35:18 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:35:18 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:35:26 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:35:26 INFO  : 測試_Русский___ě_áñ測試_Русский___ě_áñ.rclone_chunk.001_aq3kn1: Moved (server-side) to: 測試_Русский___ě_áñ測試_Русский___ě_áñ
2025/02/07 02:35:26 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:35:26 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:35:26 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:35:27 DEBUG : pacer: Reducing sleep to 15ms
NFDx2 checkfile vs. both remote (without normalization)
2025/02/07 02:35:28 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:35:28 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: sum not found
2025/02/07 02:35:28 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali'
2025/02/07 02:35:28 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali': 1 files missing
2025/02/07 02:35:28 NOTICE: 1 hashes missing
2025/02/07 02:35:28 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali': 2 differences found
2025/02/07 02:35:28 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali': 2 errors while checking
NFDx2 checkfile vs. both remote (with normalization)
2025/02/07 02:35:33 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:35:37 DEBUG : 測試_Русский___ě_áñ測試_Русский___ě_áñ: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:35:37 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali': 0 differences found
2025/02/07 02:35:37 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali': 1 matching files
2025/02/07 02:35:37 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-joseqan4lepu"
2025/02/07 02:35:37 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:35:37 DEBUG : Creating backend with remote "TestBox:rclone-test-joseqan4lepu"
2025/02/07 02:35:38 DEBUG : box root 'rclone-test-joseqan4lepu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:35:39 DEBUG : Reset feature "ListR"
2025/02/07 02:35:39 DEBUG : Creating backend with remote "/tmp/rclone3575314243"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu'", Local "Local file system at /tmp/rclone3575314243", Modify Window "1s"
2025/02/07 02:35:39 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:35:39 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:35:39 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:35:40 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:35:40 DEBUG : box root 'rclone-test-joseqan4lepu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:35:41 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:35:42 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:35:56 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:35:56 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:35:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:36:00 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:36:02 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:36:02 INFO  : 測試_Русский___ě_áñ測試_Русский___ě_áñ.rclone_chunk.001_aq4rfs: Moved (server-side) to: 測試_Русский___ě_áñ測試_Русский___ě_áñ
2025/02/07 02:36:07 DEBUG : pacer: Reducing sleep to 10ms
NFCx2 checkfile vs. both remote (without normalization)
2025/02/07 02:36:08 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:36:08 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:36:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:36:08 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:36:08 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: sum not found
2025/02/07 02:36:08 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu'
2025/02/07 02:36:08 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu': 1 files missing
2025/02/07 02:36:08 NOTICE: 1 hashes missing
2025/02/07 02:36:08 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu': 2 differences found
2025/02/07 02:36:08 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu': 2 errors while checking
NFCx2 checkfile vs. both remote (with normalization)
2025/02/07 02:36:12 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:36:14 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:36:14 DEBUG : 測試_Русский___ě_áñ測試_Русский___ě_áñ: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:36:14 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu': 0 differences found
2025/02/07 02:36:14 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu': 1 matching files
2025/02/07 02:36:14 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-pupocam0gizu"
2025/02/07 02:36:14 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:36:14 DEBUG : Creating backend with remote "TestBox:rclone-test-pupocam0gizu"
2025/02/07 02:36:20 DEBUG : box root 'rclone-test-pupocam0gizu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:36:20 DEBUG : Reset feature "ListR"
2025/02/07 02:36:20 DEBUG : Creating backend with remote "/tmp/rclone631666482"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu'", Local "Local file system at /tmp/rclone631666482", Modify Window "1s"
2025/02/07 02:36:23 DEBUG : box root 'rclone-test-pupocam0gizu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:36:45 INFO  : 測試_Русский___ě_áñ測試_Русский___ě_áñ.rclone_chunk.001_aq5yn3: Moved (server-side) to: 測試_Русский___ě_áñ測試_Русский___ě_áñ
2025/02/07 02:36:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:36:45 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:36:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:36:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:36:45 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:36:45 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:36:46 DEBUG : pacer: Reducing sleep to 30ms
both checkfile vs. NFDx2 remote (without normalization)
2025/02/07 02:36:46 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:36:46 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: sum not found
2025/02/07 02:36:46 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu'
2025/02/07 02:36:46 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu': 1 files missing
2025/02/07 02:36:46 NOTICE: 1 hashes missing
2025/02/07 02:36:46 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu': 2 differences found
2025/02/07 02:36:46 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu': 2 errors while checking
both checkfile vs. NFDx2 remote (with normalization)
2025/02/07 02:36:52 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:36:53 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:36:53 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:36:53 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
2025/02/07 02:36:53 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:36:53 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:36:53 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
2025/02/07 02:36:54 DEBUG : pacer: Reducing sleep to 50.625ms
2025/02/07 02:36:54 DEBUG : 測試_Русский___ě_áñ測試_Русский___ě_áñ: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:36:54 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu': 0 differences found
2025/02/07 02:36:54 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu': 1 matching files
2025/02/07 02:36:54 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-miyubet0vere"
2025/02/07 02:36:54 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 02:36:54 DEBUG : Creating backend with remote "TestBox:rclone-test-miyubet0vere"
2025/02/07 02:37:03 DEBUG : box root 'rclone-test-miyubet0vere': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:37:03 DEBUG : Reset feature "ListR"
2025/02/07 02:37:03 DEBUG : Creating backend with remote "/tmp/rclone1408990597"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere'", Local "Local file system at /tmp/rclone1408990597", Modify Window "1s"
2025/02/07 02:37:06 DEBUG : box root 'rclone-test-miyubet0vere': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 02:37:18 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:37:18 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:37:18 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:37:21 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:37:23 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:37:24 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:37:24 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:37:24 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/02/07 02:37:28 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:37:41 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:37:46 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:37:47 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:37:47 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:37:47 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:37:48 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:37:48 INFO  : 測試_Русский___ě_áñ測試_Русский___ě_áñ.rclone_chunk.001_aq7ipn: Moved (server-side) to: 測試_Русский___ě_áñ測試_Русский___ě_áñ
2025/02/07 02:37:48 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:37:48 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:37:48 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:37:49 DEBUG : pacer: Reducing sleep to 22.5ms
both checkfile vs. NFCx2 remote (without normalization)
2025/02/07 02:37:56 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:37:56 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: sum not found
2025/02/07 02:37:56 ERROR : 測試_Русский___ě_áñ測試_Русский___ě_áñ: file not in Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere'
2025/02/07 02:37:56 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere': 1 files missing
2025/02/07 02:37:56 NOTICE: 1 hashes missing
2025/02/07 02:37:56 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere': 2 differences found
2025/02/07 02:37:56 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere': 2 errors while checking
both checkfile vs. NFCx2 remote (with normalization)
2025/02/07 02:37:57 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:38:02 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:38:02 DEBUG : 測試_Русский___ě_áñ測試_Русский___ě_áñ: md5 = 65a8e27d8879283831b664bd8b7f0ad4 OK
2025/02/07 02:38:02 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere': 0 differences found
2025/02/07 02:38:02 NOTICE: Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere': 1 matching files
2025/02/07 02:38:02 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-miyubet0vere': Purge remote
2025/02/07 02:38:05 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-pupocam0gizu': Purge remote
2025/02/07 02:38:12 DEBUG : pacer: Reducing sleep to 37.96875ms
2025/02/07 02:38:12 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-joseqan4lepu': Purge remote
2025/02/07 02:38:12 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:38:12 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:38:12 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:38:19 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:38:19 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-wegetof5xali': Purge remote
2025/02/07 02:38:21 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-poheyot4quca': Purge remote
2025/02/07 02:38:30 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-roqufec9dizu': Purge remote
2025/02/07 02:38:42 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-gamuyos8giha': Purge remote
2025/02/07 02:38:42 DEBUG : Config file has changed externally - reloading
2025/02/07 02:38:42 DEBUG : TestBox: Loaded invalid token from config file - ignoring
2025/02/07 02:38:56 DEBUG : Config file has changed externally - reloading
2025/02/07 02:38:56 DEBUG : Saving config "token" in section "TestBox" of the config file
2025/02/07 02:38:56 DEBUG : TestBox: Saved new token in config file
2025/02/07 02:38:56 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:38:56 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:38:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:38:59 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:38:59 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-coyefon9peqo': Purge remote
2025/02/07 02:38:59 DEBUG : TestBox: Loaded fresh token from config file
2025/02/07 02:38:59 DEBUG : TestBox: Loaded new refresh token from config file
2025/02/07 02:39:01 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-wabawag2nijo': Purge remote
2025/02/07 02:39:01 DEBUG : TestBox: Loaded fresh token from config file
2025/02/07 02:39:01 DEBUG : TestBox: Loaded new refresh token from config file
2025/02/07 02:39:02 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:39:02 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:39:02 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:39:15 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:39:15 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-loqexuz9heki': Purge remote
2025/02/07 02:39:15 DEBUG : TestBox: Loaded fresh token from config file
2025/02/07 02:39:15 DEBUG : TestBox: Loaded new refresh token from config file
2025/02/07 02:39:21 DEBUG : pacer: Reducing sleep to 17.105229ms
--- PASS: TestApplyTransforms (443.81s)
=== RUN   TestTruncateString
--- PASS: TestTruncateString (0.00s)
=== RUN   TestCopyFile
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:39:21 DEBUG : TestBox: Loaded fresh token from config file
2025/02/07 02:39:21 DEBUG : TestBox: Loaded new refresh token from config file
2025/02/07 02:39:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:39:21 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:39:21 DEBUG : pacer: Rate limited, increasing sleep to 120ms
2025/02/07 02:39:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:39:21 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:39:21 DEBUG : pacer: Rate limited, increasing sleep to 240ms
2025/02/07 02:39:22 DEBUG : pacer: Reducing sleep to 180ms
2025/02/07 02:39:22 DEBUG : file1: Need to transfer - File not found at Destination
2025/02/07 02:39:30 DEBUG : pacer: Reducing sleep to 135ms
2025/02/07 02:39:31 DEBUG : pacer: Reducing sleep to 101.25ms
2025/02/07 02:39:31 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:39:31 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:39:31 DEBUG : pacer: Rate limited, increasing sleep to 202.5ms
2025/02/07 02:39:35 DEBUG : pacer: Reducing sleep to 151.875ms
2025/02/07 02:39:37 DEBUG : pacer: Reducing sleep to 113.90625ms
2025/02/07 02:39:40 DEBUG : pacer: Reducing sleep to 85.429687ms
2025/02/07 02:39:54 DEBUG : pacer: Reducing sleep to 64.072265ms
2025/02/07 02:39:54 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:39:54 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:39:54 DEBUG : pacer: Rate limited, increasing sleep to 128.14453ms
2025/02/07 02:39:58 DEBUG : pacer: Reducing sleep to 96.108397ms
2025/02/07 02:39:59 DEBUG : pacer: Reducing sleep to 72.081297ms
2025/02/07 02:40:06 DEBUG : pacer: Reducing sleep to 54.060972ms
2025/02/07 02:40:06 INFO  : sub/file2.rclone_chunk.001_aqb3ey: Moved (server-side) to: sub/file2
2025/02/07 02:40:06 INFO  : file1: Copied (new) to: sub/file2
2025/02/07 02:40:07 DEBUG : pacer: Reducing sleep to 40.545729ms
2025/02/07 02:40:07 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:07 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:07 DEBUG : pacer: Rate limited, increasing sleep to 81.091458ms
2025/02/07 02:40:07 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:07 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:07 DEBUG : pacer: Rate limited, increasing sleep to 162.182916ms
2025/02/07 02:40:08 DEBUG : pacer: Reducing sleep to 121.637187ms
2025/02/07 02:40:08 DEBUG : pacer: Reducing sleep to 91.22789ms
2025/02/07 02:40:09 DEBUG : pacer: Reducing sleep to 68.420917ms
2025/02/07 02:40:10 DEBUG : pacer: Reducing sleep to 51.315687ms
2025/02/07 02:40:10 DEBUG : file1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/07 02:40:10 DEBUG : file1: Unchanged skipping
2025/02/07 02:40:10 DEBUG : pacer: Reducing sleep to 38.486765ms
2025/02/07 02:40:10 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:10 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:10 DEBUG : pacer: Rate limited, increasing sleep to 76.97353ms
2025/02/07 02:40:16 DEBUG : pacer: Reducing sleep to 57.730147ms
2025/02/07 02:40:16 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo': don't need to copy/move sub/file2, it is already at target location
2025/02/07 02:40:16 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:16 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:16 DEBUG : pacer: Rate limited, increasing sleep to 115.460294ms
2025/02/07 02:40:16 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:16 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:16 DEBUG : pacer: Rate limited, increasing sleep to 230.920588ms
2025/02/07 02:40:17 DEBUG : pacer: Reducing sleep to 173.190441ms
2025/02/07 02:40:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:17 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:17 DEBUG : pacer: Rate limited, increasing sleep to 346.380882ms
2025/02/07 02:40:26 DEBUG : pacer: Reducing sleep to 259.785661ms
2025/02/07 02:40:27 DEBUG : pacer: Reducing sleep to 194.839245ms
2025/02/07 02:40:27 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:27 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:27 DEBUG : pacer: Rate limited, increasing sleep to 389.67849ms
2025/02/07 02:40:32 DEBUG : pacer: Reducing sleep to 292.258867ms
2025/02/07 02:40:33 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:33 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:33 DEBUG : pacer: Rate limited, increasing sleep to 584.517734ms
2025/02/07 02:40:35 DEBUG : pacer: Reducing sleep to 438.3883ms
2025/02/07 02:40:38 DEBUG : pacer: Reducing sleep to 328.791225ms
2025/02/07 02:40:39 DEBUG : pacer: Reducing sleep to 246.593418ms
--- PASS: TestCopyFile (77.92s)
=== RUN   TestCopyLongFile
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    copy_test.go:153: Test only runs on local
2025/02/07 02:40:39 DEBUG : pacer: Reducing sleep to 184.945063ms
2025/02/07 02:40:40 DEBUG : pacer: Reducing sleep to 138.708797ms
--- SKIP: TestCopyLongFile (1.18s)
=== RUN   TestCopyFileBackupDir
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:40:40 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:40:40 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:40:40 DEBUG : pacer: Rate limited, increasing sleep to 277.417594ms
2025/02/07 02:40:41 DEBUG : pacer: Reducing sleep to 208.063195ms
2025/02/07 02:40:41 DEBUG : pacer: Reducing sleep to 156.047396ms
2025/02/07 02:40:49 DEBUG : pacer: Reducing sleep to 117.035547ms
2025/02/07 02:40:49 DEBUG : pacer: Reducing sleep to 87.77666ms
2025/02/07 02:40:55 DEBUG : pacer: Reducing sleep to 65.832495ms
2025/02/07 02:41:00 DEBUG : pacer: Reducing sleep to 49.374371ms
2025/02/07 02:41:00 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:00 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:00 DEBUG : pacer: Rate limited, increasing sleep to 98.748742ms
2025/02/07 02:41:01 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:01 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:01 DEBUG : pacer: Rate limited, increasing sleep to 197.497484ms
2025/02/07 02:41:08 DEBUG : pacer: Reducing sleep to 148.123113ms
2025/02/07 02:41:08 DEBUG : pacer: Reducing sleep to 111.092334ms
2025/02/07 02:41:09 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:09 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:09 DEBUG : pacer: Rate limited, increasing sleep to 222.184668ms
2025/02/07 02:41:10 DEBUG : pacer: Reducing sleep to 166.638501ms
2025/02/07 02:41:10 INFO  : dst/file1.rclone_chunk.001_aqd2mi: Moved (server-side) to: dst/file1
2025/02/07 02:41:10 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:10 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:10 DEBUG : pacer: Rate limited, increasing sleep to 333.277002ms
2025/02/07 02:41:10 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:10 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:10 DEBUG : pacer: Rate limited, increasing sleep to 666.554004ms
2025/02/07 02:41:11 DEBUG : pacer: Reducing sleep to 499.915503ms
2025/02/07 02:41:11 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:11 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:11 DEBUG : pacer: Rate limited, increasing sleep to 999.831006ms
2025/02/07 02:41:12 DEBUG : pacer: Reducing sleep to 749.873254ms
2025/02/07 02:41:13 DEBUG : pacer: Reducing sleep to 562.40494ms
2025/02/07 02:41:14 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:14 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:14 DEBUG : pacer: Rate limited, increasing sleep to 1.12480988s
2025/02/07 02:41:14 DEBUG : pacer: Reducing sleep to 843.60741ms
2025/02/07 02:41:15 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:15 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:15 DEBUG : pacer: Rate limited, increasing sleep to 1.68721482s
2025/02/07 02:41:17 DEBUG : pacer: Reducing sleep to 1.265411115s
2025/02/07 02:41:17 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/backup"
2025/02/07 02:41:17 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/backup"
2025/02/07 02:41:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:19 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:41:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:19 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:19 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:41:20 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:41:20 DEBUG : Reset feature "ListR"
2025/02/07 02:41:20 DEBUG : dst/file1: Sizes differ (src 14 vs dst 18)
2025/02/07 02:41:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:20 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:20 DEBUG : pacer: Rate limited, increasing sleep to 60ms
2025/02/07 02:41:24 DEBUG : pacer: Reducing sleep to 45ms
2025/02/07 02:41:24 DEBUG : dst/file1: move non-chunked object...
2025/02/07 02:41:24 DEBUG : pacer: Reducing sleep to 33.75ms
2025/02/07 02:41:26 DEBUG : pacer: Reducing sleep to 25.3125ms
2025/02/07 02:41:27 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/02/07 02:41:33 DEBUG : pacer: Reducing sleep to 14.238281ms
2025/02/07 02:41:41 DEBUG : pacer: Reducing sleep to 10.67871ms
2025/02/07 02:41:41 INFO  : dst/file1: Moved (server-side)
2025/02/07 02:41:41 INFO  : dst/file1: Moved (server-side)
2025/02/07 02:41:41 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:41 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:41 DEBUG : pacer: Rate limited, increasing sleep to 2s
2025/02/07 02:41:43 DEBUG : pacer: Reducing sleep to 1.5s
2025/02/07 02:41:43 DEBUG : dst/file1: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:41:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:41:45 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:41:45 DEBUG : pacer: Rate limited, increasing sleep to 2s
2025/02/07 02:41:47 DEBUG : pacer: Reducing sleep to 1.5s
2025/02/07 02:41:56 DEBUG : pacer: Reducing sleep to 1.125s
2025/02/07 02:42:02 DEBUG : pacer: Reducing sleep to 843.75ms
2025/02/07 02:42:03 DEBUG : pacer: Reducing sleep to 632.8125ms
2025/02/07 02:42:04 DEBUG : pacer: Reducing sleep to 474.609375ms
2025/02/07 02:42:08 DEBUG : pacer: Reducing sleep to 355.957031ms
2025/02/07 02:42:08 INFO  : dst/file1.rclone_chunk.001_aqesbm: Moved (server-side) to: dst/file1
2025/02/07 02:42:08 INFO  : dst/file1: Copied (new)
2025/02/07 02:42:09 DEBUG : pacer: Reducing sleep to 266.967773ms
2025/02/07 02:42:10 DEBUG : pacer: Reducing sleep to 200.225829ms
2025/02/07 02:42:11 DEBUG : pacer: Reducing sleep to 150.169371ms
2025/02/07 02:42:12 DEBUG : pacer: Reducing sleep to 112.627028ms
2025/02/07 02:42:12 DEBUG : pacer: Reducing sleep to 84.470271ms
2025/02/07 02:42:13 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:42:13 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:42:13 DEBUG : pacer: Rate limited, increasing sleep to 168.940542ms
2025/02/07 02:42:16 DEBUG : pacer: Reducing sleep to 126.705406ms
2025/02/07 02:42:18 DEBUG : pacer: Reducing sleep to 95.029054ms
2025/02/07 02:42:21 DEBUG : pacer: Reducing sleep to 71.27179ms
2025/02/07 02:42:21 DEBUG : pacer: Reducing sleep to 53.453842ms
2025/02/07 02:42:34 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/02/07 02:42:34 DEBUG : pacer: Rate limited, increasing sleep to 106.907684ms
2025/02/07 02:42:35 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:42:35 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:42:35 DEBUG : pacer: Rate limited, increasing sleep to 213.815368ms
2025/02/07 02:42:40 DEBUG : pacer: Reducing sleep to 160.361526ms
2025/02/07 02:42:41 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:42:41 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:42:41 DEBUG : pacer: Rate limited, increasing sleep to 320.723052ms
2025/02/07 02:42:54 DEBUG : pacer: Reducing sleep to 240.542289ms
2025/02/07 02:43:02 DEBUG : pacer: Reducing sleep to 180.406716ms
2025/02/07 02:43:06 DEBUG : pacer: Reducing sleep to 135.305037ms
2025/02/07 02:43:06 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:06 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:06 DEBUG : pacer: Rate limited, increasing sleep to 270.610074ms
2025/02/07 02:43:06 DEBUG : pacer: Reducing sleep to 202.957555ms
--- PASS: TestCopyFileBackupDir (146.24s)
=== RUN   TestCopyFileCompareDest
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:43:06 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/dst"
2025/02/07 02:43:06 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/dst"
2025/02/07 02:43:16 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:16 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:16 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:43:16 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:43:16 DEBUG : Reset feature "ListR"
2025/02/07 02:43:17 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:43:17 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/CompareDest"
2025/02/07 02:43:17 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/CompareDest"
2025/02/07 02:43:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:19 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:43:20 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:43:20 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:43:20 DEBUG : Reset feature "ListR"
2025/02/07 02:43:20 DEBUG : one: Need to transfer - File not found at Destination
2025/02/07 02:43:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:21 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:21 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/02/07 02:43:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:21 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:21 DEBUG : pacer: Rate limited, increasing sleep to 45ms
2025/02/07 02:43:26 DEBUG : pacer: Reducing sleep to 33.75ms
2025/02/07 02:43:27 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:43:27 DEBUG : one: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:43:34 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:34 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:34 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:43:36 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:43:40 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:43:40 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:40 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:40 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/02/07 02:43:41 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:43:41 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:43:42 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:43:42 INFO  : one.rclone_chunk.001_aqho1t: Moved (server-side) to: one
2025/02/07 02:43:42 INFO  : one: Copied (new)
2025/02/07 02:43:43 DEBUG : pacer: Reducing sleep to 152.218166ms
2025/02/07 02:43:49 DEBUG : pacer: Reducing sleep to 114.163624ms
2025/02/07 02:43:50 DEBUG : pacer: Reducing sleep to 85.622718ms
2025/02/07 02:43:50 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:50 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:50 DEBUG : pacer: Rate limited, increasing sleep to 171.245436ms
2025/02/07 02:43:50 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:43:50 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:43:50 DEBUG : pacer: Rate limited, increasing sleep to 342.490872ms
2025/02/07 02:43:51 DEBUG : pacer: Reducing sleep to 256.868154ms
2025/02/07 02:44:01 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/02/07 02:44:03 DEBUG : pacer: Reducing sleep to 25.3125ms
2025/02/07 02:44:03 DEBUG : one: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:44:03 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:44:03 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:44:03 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:44:05 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:44:07 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:44:07 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:44:07 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:44:07 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/02/07 02:44:08 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:44:08 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:44:08 DEBUG : pacer: Rate limited, increasing sleep to 45ms
2025/02/07 02:44:08 DEBUG : pacer: Reducing sleep to 33.75ms
2025/02/07 02:44:09 DEBUG : pacer: Reducing sleep to 25.3125ms
2025/02/07 02:44:09 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:44:09 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:44:09 DEBUG : pacer: Rate limited, increasing sleep to 50.625ms
2025/02/07 02:44:10 DEBUG : pacer: Reducing sleep to 37.96875ms
2025/02/07 02:44:10 DEBUG : pacer: Reducing sleep to 28.476562ms
2025/02/07 02:44:11 DEBUG : pacer: Reducing sleep to 21.357421ms
2025/02/07 02:44:11 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:44:11 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:44:11 DEBUG : pacer: Rate limited, increasing sleep to 42.714842ms
2025/02/07 02:44:15 DEBUG : pacer: Reducing sleep to 32.036131ms
2025/02/07 02:44:15 INFO  : one: Deleted
2025/02/07 02:44:15 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:44:15 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:44:15 DEBUG : pacer: Rate limited, increasing sleep to 64.072262ms
2025/02/07 02:44:16 DEBUG : pacer: Reducing sleep to 48.054196ms
2025/02/07 02:44:16 INFO  : one.rclone_chunk.001_aqioc6: Moved (server-side) to: one
2025/02/07 02:44:16 INFO  : one: Copied (replaced existing)
2025/02/07 02:44:18 DEBUG : pacer: Reducing sleep to 192.651115ms
2025/02/07 02:44:19 DEBUG : pacer: Reducing sleep to 144.488336ms
2025/02/07 02:44:19 DEBUG : pacer: Reducing sleep to 108.366252ms
2025/02/07 02:44:24 DEBUG : pacer: Reducing sleep to 81.274689ms
2025/02/07 02:44:32 DEBUG : pacer: Reducing sleep to 60.956016ms
2025/02/07 02:44:32 DEBUG : pacer: Reducing sleep to 45.717012ms
2025/02/07 02:44:33 DEBUG : pacer: Reducing sleep to 34.287759ms
2025/02/07 02:44:36 DEBUG : pacer: Reducing sleep to 25.715819ms
2025/02/07 02:44:41 DEBUG : pacer: Reducing sleep to 19.286864ms
2025/02/07 02:44:42 DEBUG : pacer: Reducing sleep to 14.465148ms
2025/02/07 02:44:43 DEBUG : pacer: Reducing sleep to 10.848861ms
2025/02/07 02:44:43 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:45:04 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/02/07 02:45:04 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:45:04 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:45:04 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:45:04 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:45:07 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:45:07 INFO  : dst/one: Deleted
2025/02/07 02:45:22 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:45:22 INFO  : dst/one.rclone_chunk.001_aqjh3o: Moved (server-side) to: dst/one
2025/02/07 02:45:23 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:45:23 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:45:24 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:46:04 INFO  : CompareDest/one.rclone_chunk.001_aqkwgf: Moved (server-side) to: CompareDest/one
2025/02/07 02:46:08 DEBUG : pacer: Reducing sleep to 36.040647ms
2025/02/07 02:46:09 DEBUG : pacer: Reducing sleep to 27.030485ms
2025/02/07 02:46:10 DEBUG : pacer: Reducing sleep to 20.272863ms
2025/02/07 02:46:10 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/02/07 02:46:12 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/02/07 02:46:12 DEBUG : pacer: Reducing sleep to 14.238281ms
2025/02/07 02:46:13 DEBUG : pacer: Reducing sleep to 10.67871ms
2025/02/07 02:46:13 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:46:13 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/02/07 02:46:13 DEBUG : one: Destination found in --compare-dest, skipping
2025/02/07 02:46:13 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:46:13 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:46:13 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:46:14 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:46:14 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:46:14 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:46:14 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:46:16 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:46:18 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:46:23 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:46:24 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:46:34 INFO  : CompareDest/two.rclone_chunk.001_aqmkzp: Moved (server-side) to: CompareDest/two
2025/02/07 02:46:38 DEBUG : pacer: Reducing sleep to 15.204647ms
2025/02/07 02:46:38 DEBUG : two: Need to transfer - File not found at Destination
2025/02/07 02:46:40 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/02/07 02:46:40 DEBUG : two: Destination found in --compare-dest, skipping
2025/02/07 02:46:42 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:46:42 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:46:42 DEBUG : pacer: Rate limited, increasing sleep to 30.409294ms
2025/02/07 02:46:43 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:46:43 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:46:43 DEBUG : pacer: Rate limited, increasing sleep to 60.818588ms
2025/02/07 02:46:44 DEBUG : pacer: Reducing sleep to 45.613941ms
2025/02/07 02:46:44 DEBUG : two: Need to transfer - File not found at Destination
2025/02/07 02:46:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:46:45 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:46:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:46:45 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:46:46 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:46:46 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:46:46 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:46:52 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:46:52 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/02/07 02:46:52 DEBUG : two: Destination found in --compare-dest, skipping
2025/02/07 02:47:01 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:01 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:01 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:47:02 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:02 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:02 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:47:02 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:47:02 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:47:09 DEBUG : pacer: Reducing sleep to 34.210455ms
2025/02/07 02:47:09 DEBUG : two: Need to transfer - File not found at Destination
2025/02/07 02:47:12 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:47:12 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:47:13 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:47:13 DEBUG : two: Sizes differ (src 5 vs dst 3)
2025/02/07 02:47:13 DEBUG : pacer: Reducing sleep to 25.657841ms
2025/02/07 02:47:13 DEBUG : two: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:47:14 DEBUG : pacer: Reducing sleep to 19.24338ms
2025/02/07 02:47:15 DEBUG : pacer: Reducing sleep to 14.432535ms
2025/02/07 02:47:17 DEBUG : pacer: Reducing sleep to 10.824401ms
2025/02/07 02:47:18 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:47:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:19 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:47:19 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:47:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:20 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:20 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:47:31 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:47:31 INFO  : two.rclone_chunk.001_aqny2h: Moved (server-side) to: two
2025/02/07 02:47:31 INFO  : two: Copied (new)
2025/02/07 02:47:34 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:47:35 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:47:35 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:47:39 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:39 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:39 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:47:42 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:47:42 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:42 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:42 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:47:44 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:47:49 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:47:51 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:47:52 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestCopyFileCompareDest (286.80s)
=== RUN   TestCopyFileCopyDest
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:47:53 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/dst"
2025/02/07 02:47:53 DEBUG : Config file has changed externally - reloading
2025/02/07 02:47:53 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/dst"
2025/02/07 02:47:53 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:53 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:53 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:47:54 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:54 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:54 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:47:54 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:47:55 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:55 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:55 DEBUG : pacer: Rate limited, increasing sleep to 60ms
2025/02/07 02:47:55 DEBUG : pacer: Reducing sleep to 45ms
2025/02/07 02:47:55 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:47:55 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:47:55 DEBUG : pacer: Rate limited, increasing sleep to 90ms
2025/02/07 02:48:01 DEBUG : pacer: Reducing sleep to 67.5ms
2025/02/07 02:48:01 DEBUG : pacer: Reducing sleep to 50.625ms
2025/02/07 02:48:01 DEBUG : Reset feature "ListR"
2025/02/07 02:48:01 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:48:01 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:48:01 DEBUG : pacer: Rate limited, increasing sleep to 101.25ms
2025/02/07 02:48:02 DEBUG : pacer: Reducing sleep to 75.9375ms
2025/02/07 02:48:02 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/CopyDest"
2025/02/07 02:48:02 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/CopyDest"
2025/02/07 02:48:03 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:48:03 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:48:03 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:48:03 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:48:03 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:48:03 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:48:06 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:48:07 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:48:08 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:48:09 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:48:09 DEBUG : Reset feature "ListR"
2025/02/07 02:48:09 DEBUG : one: Need to transfer - File not found at Destination
2025/02/07 02:48:10 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:48:10 DEBUG : pacer: Reducing sleep to 56.953125ms
2025/02/07 02:48:10 DEBUG : one: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:48:15 DEBUG : pacer: Reducing sleep to 42.714843ms
2025/02/07 02:48:15 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:48:15 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:48:15 DEBUG : pacer: Rate limited, increasing sleep to 85.429686ms
2025/02/07 02:48:27 DEBUG : pacer: Reducing sleep to 64.072264ms
2025/02/07 02:48:28 DEBUG : pacer: Reducing sleep to 48.054198ms
2025/02/07 02:48:30 DEBUG : pacer: Reducing sleep to 36.040648ms
2025/02/07 02:48:42 DEBUG : pacer: Reducing sleep to 27.030486ms
2025/02/07 02:48:43 DEBUG : pacer: Reducing sleep to 20.272864ms
2025/02/07 02:48:43 DEBUG : pacer: Reducing sleep to 15.204648ms
2025/02/07 02:48:44 DEBUG : pacer: Reducing sleep to 11.403486ms
2025/02/07 02:48:44 INFO  : one.rclone_chunk.001_aqpjca: Moved (server-side) to: one
2025/02/07 02:48:44 INFO  : one: Copied (new)
2025/02/07 02:48:54 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:48:56 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/02/07 02:48:56 DEBUG : one: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:49:04 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:49:04 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:49:04 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:49:05 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:49:05 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:49:05 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:49:05 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/02/07 02:49:08 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:49:11 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:49:11 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:49:11 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:49:11 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
2025/02/07 02:49:18 DEBUG : pacer: Reducing sleep to 25.3125ms
2025/02/07 02:49:20 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/02/07 02:49:20 INFO  : one: Deleted
2025/02/07 02:49:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:49:20 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:49:20 DEBUG : pacer: Rate limited, increasing sleep to 37.96875ms
2025/02/07 02:49:24 DEBUG : pacer: Reducing sleep to 28.476562ms
2025/02/07 02:49:24 INFO  : one.rclone_chunk.001_aqqtqk: Moved (server-side) to: one
2025/02/07 02:49:24 INFO  : one: Copied (replaced existing)
2025/02/07 02:49:42 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:49:42 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:49:42 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:49:44 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:49:44 INFO  : dst/one: Deleted
2025/02/07 02:49:45 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:49:45 INFO  : dst/one.rclone_chunk.001_aqrorq: Moved (server-side) to: dst/one
2025/02/07 02:49:46 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:50:08 INFO  : CopyDest/one.rclone_chunk.001_aqs7us: Moved (server-side) to: CopyDest/one
2025/02/07 02:50:09 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:50:09 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:50:09 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms
2025/02/07 02:50:10 DEBUG : pacer: Reducing sleep to 42.714843ms
2025/02/07 02:50:11 DEBUG : pacer: Reducing sleep to 32.036132ms
2025/02/07 02:50:11 DEBUG : pacer: Reducing sleep to 24.027099ms
2025/02/07 02:50:11 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/BackupDir"
2025/02/07 02:50:11 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/BackupDir"
2025/02/07 02:50:11 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:50:11 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:50:11 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:50:14 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:50:15 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:50:18 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:50:22 DEBUG : Reset feature "ListR"
2025/02/07 02:50:22 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/02/07 02:50:22 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:50:22 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:50:22 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:50:22 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:50:23 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:50:24 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:50:25 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/02/07 02:50:25 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/02/07 02:50:26 DEBUG : one: move non-chunked object...
2025/02/07 02:50:34 INFO  : one: Moved (server-side)
2025/02/07 02:50:34 INFO  : one: Moved (server-side)
2025/02/07 02:50:34 DEBUG : one: copy non-chunked object...
2025/02/07 02:50:35 DEBUG : pacer: Reducing sleep to 18.020324ms
2025/02/07 02:50:37 DEBUG : pacer: Reducing sleep to 13.515243ms
2025/02/07 02:50:37 INFO  : one: Copied (server-side copy)
2025/02/07 02:50:37 DEBUG : one: Destination found in --copy-dest, using server-side copy
2025/02/07 02:50:53 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:50:53 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:50:53 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:50:54 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:50:55 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:51:15 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/02/07 02:51:15 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/02/07 02:51:17 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:51:17 INFO  : CopyDest/two.rclone_chunk.001_aqtom9: Moved (server-side) to: CopyDest/two
2025/02/07 02:51:18 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:18 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:18 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
2025/02/07 02:51:18 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:18 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:18 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
2025/02/07 02:51:18 DEBUG : pacer: Reducing sleep to 50.625ms
2025/02/07 02:51:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:19 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:19 DEBUG : pacer: Rate limited, increasing sleep to 101.25ms
2025/02/07 02:51:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:19 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:19 DEBUG : pacer: Rate limited, increasing sleep to 202.5ms
2025/02/07 02:51:19 DEBUG : pacer: Reducing sleep to 151.875ms
2025/02/07 02:51:19 DEBUG : pacer: Reducing sleep to 113.90625ms
2025/02/07 02:51:20 DEBUG : pacer: Reducing sleep to 85.429687ms
2025/02/07 02:51:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:20 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:20 DEBUG : pacer: Rate limited, increasing sleep to 27.030486ms
2025/02/07 02:51:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:20 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:20 DEBUG : pacer: Rate limited, increasing sleep to 54.060972ms
2025/02/07 02:51:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:20 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:20 DEBUG : pacer: Rate limited, increasing sleep to 108.121944ms
2025/02/07 02:51:21 DEBUG : pacer: Reducing sleep to 81.091458ms
2025/02/07 02:51:21 DEBUG : two: Need to transfer - File not found at Destination
2025/02/07 02:51:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:21 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:21 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:51:22 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:51:26 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:51:26 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/02/07 02:51:26 DEBUG : two: copy non-chunked object...
2025/02/07 02:51:27 DEBUG : pacer: Reducing sleep to 60.818593ms
2025/02/07 02:51:27 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:27 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:27 DEBUG : pacer: Rate limited, increasing sleep to 121.637186ms
2025/02/07 02:51:34 DEBUG : pacer: Reducing sleep to 91.227889ms
2025/02/07 02:51:34 INFO  : two: Copied (server-side copy)
2025/02/07 02:51:34 DEBUG : two: Destination found in --copy-dest, using server-side copy
2025/02/07 02:51:34 DEBUG : pacer: Reducing sleep to 64.072265ms
2025/02/07 02:51:35 DEBUG : pacer: Reducing sleep to 48.054198ms
2025/02/07 02:51:38 DEBUG : pacer: Reducing sleep to 36.040648ms
2025/02/07 02:51:44 DEBUG : pacer: Reducing sleep to 27.030486ms
2025/02/07 02:51:45 DEBUG : pacer: Reducing sleep to 68.420916ms
2025/02/07 02:51:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:45 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:45 DEBUG : pacer: Rate limited, increasing sleep to 136.841832ms
2025/02/07 02:51:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:45 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:45 DEBUG : pacer: Rate limited, increasing sleep to 273.683664ms
2025/02/07 02:51:48 DEBUG : pacer: Reducing sleep to 205.262748ms
2025/02/07 02:51:48 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:48 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:48 DEBUG : pacer: Rate limited, increasing sleep to 410.525496ms
2025/02/07 02:51:48 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:48 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:48 DEBUG : pacer: Rate limited, increasing sleep to 821.050992ms
2025/02/07 02:51:48 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:51:48 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:51:48 DEBUG : pacer: Rate limited, increasing sleep to 1.642101984s
2025/02/07 02:51:50 DEBUG : pacer: Reducing sleep to 1.231576488s
2025/02/07 02:51:50 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/02/07 02:51:50 DEBUG : two: Unchanged skipping
2025/02/07 02:51:50 DEBUG : pacer: Reducing sleep to 20.272864ms
2025/02/07 02:51:51 DEBUG : pacer: Reducing sleep to 15.204648ms
2025/02/07 02:51:51 DEBUG : pacer: Reducing sleep to 11.403486ms
2025/02/07 02:51:57 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:52:14 INFO  : CopyDest/three.rclone_chunk.001_aqvvsf: Moved (server-side) to: CopyDest/three
2025/02/07 02:52:32 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:52:32 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:52:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:52:32 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:52:32 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:52:33 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:52:34 DEBUG : pacer: Reducing sleep to 923.682366ms
2025/02/07 02:52:34 DEBUG : three: Need to transfer - File not found at Destination
2025/02/07 02:52:35 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:52:36 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:52:36 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:52:37 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:52:37 DEBUG : three: Sizes differ (src 7 vs dst 5)
2025/02/07 02:52:37 DEBUG : three: Destination not found in --copy-dest
2025/02/07 02:52:38 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:52:38 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:52:38 DEBUG : pacer: Rate limited, increasing sleep to 1.847364732s
2025/02/07 02:52:38 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:52:38 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:52:38 DEBUG : pacer: Rate limited, increasing sleep to 2s
2025/02/07 02:52:41 DEBUG : pacer: Reducing sleep to 1.5s
2025/02/07 02:52:41 DEBUG : three: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:52:52 DEBUG : pacer: Reducing sleep to 1.125s
2025/02/07 02:52:52 DEBUG : pacer: Reducing sleep to 843.75ms
2025/02/07 02:52:56 DEBUG : pacer: Reducing sleep to 632.8125ms
2025/02/07 02:52:56 DEBUG : pacer: Reducing sleep to 474.609375ms
2025/02/07 02:52:57 DEBUG : pacer: Reducing sleep to 355.957031ms
2025/02/07 02:52:58 DEBUG : pacer: Reducing sleep to 266.967773ms
2025/02/07 02:52:58 INFO  : three.rclone_chunk.001_aqx2gj: Moved (server-side) to: three
2025/02/07 02:52:58 INFO  : three: Copied (new)
2025/02/07 02:53:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:53:17 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:53:17 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:53:25 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:53:29 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:53:32 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestCopyFileCopyDest (346.70s)
=== RUN   TestCopyInplace
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    copy_test.go:370: Partial uploads not supported
--- SKIP: TestCopyInplace (1.23s)
=== RUN   TestCopyLongFileName
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    copy_test.go:403: Partial uploads not supported
--- SKIP: TestCopyLongFileName (1.22s)
=== RUN   TestCopyFileMaxTransfer
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 02:53:43 DEBUG : TestCopyFileMaxTransfer/file1: Need to transfer - File not found at Destination
2025/02/07 02:53:44 DEBUG : TestCopyFileMaxTransfer/file1: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:54:27 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:54:27 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:54:27 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:54:27 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:54:27 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:54:27 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:54:34 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:54:34 INFO  : TestCopyFileMaxTransfer/file1.rclone_chunk.001_aqytnb: Moved (server-side) to: TestCopyFileMaxTransfer/file1
2025/02/07 02:54:34 INFO  : TestCopyFileMaxTransfer/file1: Copied (new)
2025/02/07 02:54:34 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:54:34 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:54:34 DEBUG : pacer: Rate limited, increasing sleep to 60ms
2025/02/07 02:54:40 DEBUG : pacer: Reducing sleep to 45ms
2025/02/07 02:54:45 DEBUG : pacer: Reducing sleep to 33.75ms
2025/02/07 02:54:45 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:54:45 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:54:45 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
2025/02/07 02:54:49 DEBUG : pacer: Reducing sleep to 50.625ms
2025/02/07 02:54:49 DEBUG : TestCopyFileMaxTransfer/file2: Need to transfer - File not found at Destination
2025/02/07 02:54:50 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:54:50 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:54:50 DEBUG : pacer: Rate limited, increasing sleep to 101.25ms
2025/02/07 02:54:50 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:54:50 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:54:50 DEBUG : pacer: Rate limited, increasing sleep to 202.5ms
2025/02/07 02:54:55 DEBUG : pacer: Reducing sleep to 151.875ms
2025/02/07 02:54:55 DEBUG : TestCopyFileMaxTransfer/file2: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:54:56 DEBUG : pacer: Reducing sleep to 113.90625ms
2025/02/07 02:55:08 DEBUG : pacer: Reducing sleep to 85.429687ms
2025/02/07 02:55:32 DEBUG : pacer: Reducing sleep to 64.072265ms
2025/02/07 02:55:32 DEBUG : pacer: Reducing sleep to 48.054198ms
2025/02/07 02:55:54 DEBUG : pacer: Reducing sleep to 36.040648ms
2025/02/07 02:55:55 DEBUG : pacer: Reducing sleep to 27.030486ms
2025/02/07 02:56:17 DEBUG : pacer: Reducing sleep to 20.272864ms
2025/02/07 02:56:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:56:17 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:56:17 DEBUG : pacer: Rate limited, increasing sleep to 40.545728ms
2025/02/07 02:56:18 DEBUG : pacer: Reducing sleep to 30.409296ms
2025/02/07 02:56:41 DEBUG : pacer: Reducing sleep to 22.806972ms
2025/02/07 02:56:42 DEBUG : pacer: Reducing sleep to 17.105229ms
2025/02/07 02:57:00 DEBUG : pacer: Reducing sleep to 12.828921ms
2025/02/07 02:57:01 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:57:16 DEBUG : pacer: low level retry 1/1 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/02/07 02:57:16 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:57:16 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:57:16 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:57:16 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 02:57:26 DEBUG : pacer: Reducing sleep to 30ms
2025/02/07 02:57:32 DEBUG : pacer: Reducing sleep to 22.5ms
2025/02/07 02:57:37 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 02:57:42 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 02:58:01 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/02/07 02:58:01 DEBUG : pacer: Rate limited, increasing sleep to 25.3125ms
2025/02/07 02:58:04 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/02/07 02:58:04 DEBUG : TestCopyFileMaxTransfer/file2: Received error: Error "unavailable" (503): Service is temporarily unavailable - low level retry 0/10
2025/02/07 02:58:04 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:58:04 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:58:04 DEBUG : pacer: Rate limited, increasing sleep to 37.96875ms
2025/02/07 02:58:05 DEBUG : pacer: Reducing sleep to 28.476562ms
2025/02/07 02:58:05 DEBUG : TestCopyFileMaxTransfer/file2: skip slow MD5 on source file, hashing in-transit
2025/02/07 02:58:06 DEBUG : pacer: Reducing sleep to 21.357421ms
2025/02/07 02:58:07 DEBUG : pacer: Reducing sleep to 16.018065ms
2025/02/07 02:58:17 DEBUG : pacer: Reducing sleep to 12.013548ms
2025/02/07 02:58:18 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 02:58:28 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 02:58:28 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 02:58:28 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 02:58:30 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 02:58:43 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 02:58:43 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 03:00:10 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:00:10 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:00:10 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:00:10 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 03:00:34 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 03:00:36 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 03:01:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:01:21 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:01:21 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:01:21 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 03:01:39 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 03:01:40 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:01:40 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:01:40 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/02/07 03:01:42 DEBUG : pacer: Reducing sleep to 16.875ms
2025/02/07 03:02:01 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/02/07 03:02:01 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 03:04:51 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:04:51 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:04:51 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:04:51 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 03:04:55 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 03:04:58 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 03:05:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:05:21 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:05:21 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:05:21 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 03:05:24 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 03:05:26 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 03:05:42 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:05:42 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:05:42 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:05:42 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:05:42 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:05:42 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/07 03:05:43 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:05:43 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:05:43 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/02/07 03:05:44 DEBUG : pacer: Reducing sleep to 60ms
2025/02/07 03:05:47 DEBUG : pacer: Reducing sleep to 45ms
2025/02/07 03:05:48 DEBUG : pacer: Reducing sleep to 33.75ms
2025/02/07 03:05:48 DEBUG : pacer: Reducing sleep to 25.3125ms
2025/02/07 03:05:51 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/02/07 03:05:53 DEBUG : pacer: Reducing sleep to 14.238281ms
2025/02/07 03:05:53 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:05:53 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:05:53 DEBUG : pacer: Rate limited, increasing sleep to 28.476562ms
2025/02/07 03:05:55 DEBUG : pacer: Reducing sleep to 21.357421ms
2025/02/07 03:05:55 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:05:55 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:05:55 DEBUG : pacer: Rate limited, increasing sleep to 42.714842ms
2025/02/07 03:05:57 DEBUG : pacer: Reducing sleep to 32.036131ms
2025/02/07 03:06:07 DEBUG : pacer: Reducing sleep to 24.027098ms
2025/02/07 03:06:11 DEBUG : pacer: Reducing sleep to 18.020323ms
2025/02/07 03:06:13 DEBUG : pacer: Reducing sleep to 13.515242ms
2025/02/07 03:06:15 DEBUG : pacer: Reducing sleep to 10.136431ms
2025/02/07 03:06:15 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:06:15 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:06:15 DEBUG : pacer: Rate limited, increasing sleep to 20.272862ms
2025/02/07 03:06:17 DEBUG : pacer: Reducing sleep to 15.204646ms
2025/02/07 03:06:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:06:17 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:06:17 DEBUG : pacer: Rate limited, increasing sleep to 30.409292ms
2025/02/07 03:06:19 DEBUG : pacer: Reducing sleep to 22.806969ms
2025/02/07 03:06:22 DEBUG : pacer: Reducing sleep to 17.105226ms
2025/02/07 03:06:24 DEBUG : pacer: Reducing sleep to 12.828919ms
2025/02/07 03:06:31 DEBUG : pacer: Reducing sleep to 10ms
2025/02/07 03:07:24 ERROR : TestCopyFileMaxTransfer/file2: Failed to copy: Post "https://upload.box.com/api/2.0/files/content": failed to copy data: max transfer limit reached as set by --max-transfer
2025/02/07 03:07:28 DEBUG : TestCopyFileMaxTransfer/file3: Need to transfer - File not found at Destination
    copy_test.go:494: skipping remainder of test for chunker as it involves multiple transfers
--- PASS: TestCopyFileMaxTransfer (837.18s)
=== RUN   TestDeduplicateInteractive
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
2025/02/07 03:07:40 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:07:40 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:07:40 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:07:52 DEBUG : pacer: Reducing sleep to 15ms
2025/02/07 03:07:53 DEBUG : pacer: Reducing sleep to 11.25ms
--- SKIP: TestDeduplicateInteractive (13.57s)
=== RUN   TestDeduplicateSkip
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
2025/02/07 03:07:54 DEBUG : pacer: Reducing sleep to 10ms
--- SKIP: TestDeduplicateSkip (9.14s)
=== RUN   TestDeduplicateSizeOnly
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
--- SKIP: TestDeduplicateSizeOnly (1.61s)
=== RUN   TestDeduplicateFirst
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
--- SKIP: TestDeduplicateFirst (1.20s)
=== RUN   TestDeduplicateNewest
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
--- SKIP: TestDeduplicateNewest (5.42s)
=== RUN   TestDeduplicateNewestByHash
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:36: Can't run this test without a hash
--- SKIP: TestDeduplicateNewestByHash (1.21s)
=== RUN   TestDeduplicateOldest
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
--- SKIP: TestDeduplicateOldest (6.18s)
=== RUN   TestDeduplicateLargest
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
2025/02/07 03:08:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/02/07 03:08:19 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/02/07 03:08:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/07 03:08:20 DEBUG : pacer: Reducing sleep to 15ms
--- SKIP: TestDeduplicateLargest (2.27s)
=== RUN   TestDeduplicateSmallest
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
2025/02/07 03:08:21 DEBUG : pacer: Reducing sleep to 11.25ms
2025/02/07 03:08:22 DEBUG : pacer: Reducing sleep to 10ms
--- SKIP: TestDeduplicateSmallest (1.93s)
=== RUN   TestDeduplicateRename
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:24: Can't test deduplicate - no duplicate files possible
--- SKIP: TestDeduplicateRename (3.19s)
=== RUN   TestMergeDirs
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    dedupe_test.go:256: Can't merge directories
--- SKIP: TestMergeDirs (2.47s)
=== RUN   TestListDirSorted
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:08:51 INFO  : a.txt.rclone_chunk.001_arnd7z: Moved (server-side) to: a.txt
2025/02/07 03:09:07 INFO  : zend.txt.rclone_chunk.001_aro2b6: Moved (server-side) to: zend.txt
2025/02/07 03:09:34 INFO  : sub dir/hello world.rclone_chunk.001_aroir9: Moved (server-side) to: sub dir/hello world
2025/02/07 03:09:55 INFO  : sub dir/hello world2.rclone_chunk.001_arp8j2: Moved (server-side) to: sub dir/hello world2
2025/02/07 03:10:22 INFO  : sub dir/ignore dir/.ignore.rclone_chunk.001_arptxx: Moved (server-side) to: sub dir/ignore dir/.ignore
2025/02/07 03:10:38 INFO  : sub dir/ignore dir/should be ignored.rclone_chunk.001_arqkmk: Moved (server-side) to: sub dir/ignore dir/should be ignored
2025/02/07 03:10:58 INFO  : sub dir/sub sub dir/hello world3.rclone_chunk.001_arr4ma: Moved (server-side) to: sub dir/sub sub dir/hello world3
2025/02/07 03:11:02 DEBUG : a.txt: Excluded (Size Filter)
2025/02/07 03:11:02 DEBUG : a.txt: Excluded
2025/02/07 03:11:03 DEBUG : sub dir/hello world: Excluded (Size Filter)
2025/02/07 03:11:03 DEBUG : sub dir/hello world: Excluded
2025/02/07 03:11:03 DEBUG : sub dir/hello world2: Excluded (Size Filter)
2025/02/07 03:11:03 DEBUG : sub dir/hello world2: Excluded
2025/02/07 03:11:04 DEBUG : sub dir/hello world: Excluded (Size Filter)
2025/02/07 03:11:04 DEBUG : sub dir/hello world: Excluded
2025/02/07 03:11:04 DEBUG : sub dir/hello world2: Excluded (Size Filter)
2025/02/07 03:11:04 DEBUG : sub dir/hello world2: Excluded
2025/02/07 03:11:06 DEBUG : sub dir/ignore dir: Excluded
2025/02/07 03:11:12 DEBUG : sub dir/ignore dir: Excluded
--- PASS: TestListDirSorted (188.57s)
=== RUN   TestListJSON
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:11:43 INFO  : file1.rclone_chunk.001_arsmy5: Moved (server-side) to: file1
2025/02/07 03:11:52 INFO  : sub/file2.rclone_chunk.001_arstc4: Moved (server-side) to: sub/file2
=== RUN   TestListJSON/Default
=== RUN   TestListJSON/FilesOnly
=== RUN   TestListJSON/DirsOnly
=== RUN   TestListJSON/Recurse
=== RUN   TestListJSON/SubDir
=== RUN   TestListJSON/NoModTime
=== RUN   TestListJSON/NoMimeType
=== RUN   TestListJSON/ShowHash
=== RUN   TestListJSON/HashTypes
=== RUN   TestListJSON/Metadata
--- PASS: TestListJSON (40.12s)
    --- PASS: TestListJSON/Default (1.34s)
    --- PASS: TestListJSON/FilesOnly (3.11s)
    --- PASS: TestListJSON/DirsOnly (0.70s)
    --- PASS: TestListJSON/Recurse (1.97s)
    --- PASS: TestListJSON/SubDir (0.67s)
    --- PASS: TestListJSON/NoModTime (0.71s)
    --- PASS: TestListJSON/NoMimeType (0.69s)
    --- PASS: TestListJSON/ShowHash (0.68s)
    --- PASS: TestListJSON/HashTypes (0.67s)
    --- PASS: TestListJSON/Metadata (0.68s)
=== RUN   TestStatJSON
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:12:29 INFO  : file1.rclone_chunk.001_artrdi: Moved (server-side) to: file1
2025/02/07 03:12:40 INFO  : sub/file2.rclone_chunk.001_aru2j2: Moved (server-side) to: sub/file2
=== RUN   TestStatJSON/Root
=== RUN   TestStatJSON/RootFilesOnly
=== RUN   TestStatJSON/RootDirsOnly
=== RUN   TestStatJSON/Dir
=== RUN   TestStatJSON/DirWithTrailingSlash
=== RUN   TestStatJSON/File
=== RUN   TestStatJSON/NotFound
=== RUN   TestStatJSON/DirFilesOnly
=== RUN   TestStatJSON/FileFilesOnly
=== RUN   TestStatJSON/NotFoundFilesOnly
=== RUN   TestStatJSON/DirDirsOnly
=== RUN   TestStatJSON/FileDirsOnly
=== RUN   TestStatJSON/NotFoundDirsOnly
=== RUN   TestStatJSON/RootNotFound
2025/02/07 03:12:59 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-paxodec6gefo/notfound"
2025/02/07 03:12:59 DEBUG : Config file has changed externally - reloading
2025/02/07 03:12:59 DEBUG : Creating backend with remote "TestBox:rclone-test-paxodec6gefo/notfound"
2025/02/07 03:13:06 DEBUG : Reset feature "ListR"
--- PASS: TestStatJSON (59.97s)
    --- PASS: TestStatJSON/Root (1.28s)
    --- PASS: TestStatJSON/RootFilesOnly (0.00s)
    --- PASS: TestStatJSON/RootDirsOnly (0.83s)
    --- PASS: TestStatJSON/Dir (1.99s)
    --- PASS: TestStatJSON/DirWithTrailingSlash (1.29s)
    --- PASS: TestStatJSON/File (2.42s)
    --- PASS: TestStatJSON/NotFound (1.91s)
    --- PASS: TestStatJSON/DirFilesOnly (1.16s)
    --- PASS: TestStatJSON/FileFilesOnly (2.99s)
    --- PASS: TestStatJSON/NotFoundFilesOnly (0.62s)
    --- PASS: TestStatJSON/DirDirsOnly (1.31s)
    --- PASS: TestStatJSON/FileDirsOnly (1.30s)
    --- PASS: TestStatJSON/NotFoundDirsOnly (0.70s)
    --- PASS: TestStatJSON/RootNotFound (8.21s)
=== RUN   TestMkdir
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:13:16 INFO  : Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo': Making directory
2025/02/07 03:13:17 INFO  : Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo': Making directory
--- PASS: TestMkdir (3.92s)
=== RUN   TestLsd
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:13:31 INFO  : sub dir/hello world.rclone_chunk.001_arvir0: Moved (server-side) to: sub dir/hello world
--- PASS: TestLsd (19.80s)
=== RUN   TestLs
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:13:51 INFO  : potato2.rclone_chunk.001_arw2nw: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 03:13:53 INFO  : potato2.rclone_chunk.002_arw2nw: Moved (server-side) to: potato2.rclone_chunk.002
2025/02/07 03:14:20 INFO  : empty space.rclone_chunk.001_arwq38: Moved (server-side) to: empty space
--- PASS: TestLs (52.99s)
=== RUN   TestLsWithFilesFrom
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:15:00 INFO  : potato2.rclone_chunk.001_arxjox: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 03:15:03 INFO  : potato2.rclone_chunk.002_arxjox: Moved (server-side) to: potato2.rclone_chunk.002
2025/02/07 03:15:15 INFO  : empty space.rclone_chunk.001_aryhna: Moved (server-side) to: empty space
2025/02/07 03:15:18 DEBUG : empty space: Excluded (FilesFrom Filter)
2025/02/07 03:15:18 DEBUG : empty space: Excluded
--- PASS: TestLsWithFilesFrom (58.33s)
=== RUN   TestLsLong
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:15:40 INFO  : potato2.rclone_chunk.001_arz5ml: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 03:15:41 INFO  : potato2.rclone_chunk.002_arz5ml: Moved (server-side) to: potato2.rclone_chunk.002
2025/02/07 03:15:49 INFO  : empty space.rclone_chunk.001_arzh93: Moved (server-side) to: empty space
--- PASS: TestLsLong (28.90s)
=== RUN   TestHashSums
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:16:08 INFO  : potato2.rclone_chunk.001_arzyso: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 03:16:09 INFO  : potato2.rclone_chunk.002_arzyso: Moved (server-side) to: potato2.rclone_chunk.002
2025/02/07 03:16:20 INFO  : empty space.rclone_chunk.001_as0b9r: Moved (server-side) to: empty space
--- PASS: TestHashSums (30.07s)
=== RUN   TestHashSumsWithErrors
2025/02/07 03:16:30 DEBUG : Creating backend with remote ":memory:"
2025/02/07 03:16:30 DEBUG : Config file has changed externally - reloading
2025/02/07 03:16:30 ERROR : file1: hash unsupported: hash type not supported
--- PASS: TestHashSumsWithErrors (0.00s)
=== RUN   TestHashStream
2025/02/07 03:16:30 DEBUG : Creating md5 hash of 0 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating md5 hash of 0 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating sha1 hash of 0 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating sha1 hash of 0 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating md5 hash of 12 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating md5 hash of 12 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating sha1 hash of 12 bytes read from input stream
2025/02/07 03:16:30 DEBUG : Creating sha1 hash of 12 bytes read from input stream
--- PASS: TestHashStream (0.00s)
=== RUN   TestSuffixName
--- PASS: TestSuffixName (0.00s)
=== RUN   TestCount
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:16:39 INFO  : potato2.rclone_chunk.001_as0sgy: Moved (server-side) to: potato2.rclone_chunk.001
2025/02/07 03:16:40 INFO  : potato2.rclone_chunk.002_as0sgy: Moved (server-side) to: potato2.rclone_chunk.002
2025/02/07 03:16:49 INFO  : empty space.rclone_chunk.001_as14jn: Moved (server-side) to: empty space
2025/02/07 03:16:57 INFO  : sub dir/potato3.rclone_chunk.001_as1a2v: Moved (server-side) to: sub dir/potato3
--- PASS: TestCount (42.38s)
=== RUN   TestDelete
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:17:19 INFO  : small.rclone_chunk.001_as1yf7: Moved (server-side) to: small
2025/02/07 03:17:27 INFO  : medium.rclone_chunk.001_as258q: Moved (server-side) to: medium.rclone_chunk.001
2025/02/07 03:17:28 INFO  : medium.rclone_chunk.002_as258q: Moved (server-side) to: medium.rclone_chunk.002
2025/02/07 03:17:39 INFO  : large.rclone_chunk.001_as2gk7: Moved (server-side) to: large.rclone_chunk.001
2025/02/07 03:17:40 INFO  : large.rclone_chunk.002_as2gk7: Moved (server-side) to: large.rclone_chunk.002
2025/02/07 03:17:43 DEBUG : Waiting for deletions to finish
2025/02/07 03:17:44 DEBUG : large: Excluded (Size Filter)
2025/02/07 03:17:44 DEBUG : large: Excluded
2025/02/07 03:17:45 INFO  : small: Deleted
2025/02/07 03:17:50 INFO  : medium: Deleted
--- PASS: TestDelete (46.53s)
=== RUN   TestMaxDelete
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    operations_test.go:432: Skipping test on chunker backend
--- SKIP: TestMaxDelete (2.46s)
=== RUN   TestMaxDeleteSizeLargeFile
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    operations_test.go:432: Skipping test on chunker backend
--- SKIP: TestMaxDeleteSizeLargeFile (2.49s)
=== RUN   TestMaxDeleteSize
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
    operations_test.go:432: Skipping test on chunker backend
--- SKIP: TestMaxDeleteSize (2.44s)
=== RUN   TestReadFile
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:18:13 INFO  : ReadFile.rclone_chunk.001_as3gx2: Moved (server-side) to: ReadFile
--- PASS: TestReadFile (14.02s)
=== RUN   TestRetry
2025/02/07 03:18:21 DEBUG : Received error: Wrapped EOF is retriable: EOF - low level retry 1/5
2025/02/07 03:18:21 DEBUG : Received error: Wrapped EOF is retriable: EOF - low level retry 2/5
2025/02/07 03:18:21 DEBUG : Sleeping for 10ms (as indicated by the server) to obey Retry-After error: BANG
2025/02/07 03:18:21 DEBUG : Sleeping for 10ms (as indicated by the server) to obey Retry-After error: BANG
2025/02/07 03:18:21 DEBUG : Sleeping for 10ms (as indicated by the server) to obey Retry-After error: BANG
2025/02/07 03:18:21 DEBUG : Sleeping for 10ms (as indicated by the server) to obey Retry-After error: BANG
2025/02/07 03:18:21 DEBUG : Sleeping for 10ms (as indicated by the server) to obey Retry-After error: BANG
--- PASS: TestRetry (0.05s)
=== RUN   TestCat
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:18:27 INFO  : file1.rclone_chunk.001_as3uq9: Moved (server-side) to: file1
2025/02/07 03:18:33 INFO  : file2.rclone_chunk.001_as40jo: Moved (server-side) to: file2
--- PASS: TestCat (32.63s)
=== RUN   TestPurge
2025/02/07 03:18:53 DEBUG : Creating backend with remote "TestChunkerChunk50bBox:rclone-test-dagujop0jubi"
2025/02/07 03:18:53 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/07 03:18:53 DEBUG : Creating backend with remote "TestBox:rclone-test-dagujop0jubi"
2025/02/07 03:18:54 DEBUG : box root 'rclone-test-dagujop0jubi': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:18:55 DEBUG : Reset feature "ListR"
2025/02/07 03:18:55 DEBUG : Creating backend with remote "/tmp/rclone4250867855"
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dagujop0jubi'", Local "Local file system at /tmp/rclone4250867855", Modify Window "1s"
2025/02/07 03:18:56 DEBUG : box root 'rclone-test-dagujop0jubi': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:19:08 INFO  : A1/B1/C1/one.rclone_chunk.001_as4vzm: Moved (server-side) to: A1/B1/C1/one
2025/02/07 03:19:08 INFO  : A2: Making directory
2025/02/07 03:19:10 INFO  : A1/B2: Making directory
2025/02/07 03:19:12 INFO  : A1/B2/C2: Making directory
2025/02/07 03:19:13 INFO  : A1/B1/C3: Making directory
2025/02/07 03:19:15 INFO  : A3: Making directory
2025/02/07 03:19:17 INFO  : A3/B3: Making directory
2025/02/07 03:19:19 INFO  : A3/B3/C4: Making directory
2025/02/07 03:19:26 INFO  : A1/two.rclone_chunk.001_as5ima: Moved (server-side) to: A1/two
2025/02/07 03:19:40 DEBUG : box root 'rclone-test-dagujop0jubi': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:19:40 ERROR : : error listing: directory not found
2025/02/07 03:19:40 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dagujop0jubi': Purge remote
2025/02/07 03:19:41 DEBUG : box root 'rclone-test-dagujop0jubi': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:19:41 NOTICE: purge failed: directory not found
--- PASS: TestPurge (47.22s)
=== RUN   TestRmdirsNoLeaveRoot
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:19:52 INFO  : A1/B1/C1/one.rclone_chunk.001_as621a: Moved (server-side) to: A1/B1/C1/one
2025/02/07 03:19:52 INFO  : A2: Making directory
2025/02/07 03:19:54 INFO  : A1/B2: Making directory
2025/02/07 03:19:56 INFO  : A1/B2/C2: Making directory
2025/02/07 03:19:58 INFO  : A1/B1/C3: Making directory
2025/02/07 03:19:59 INFO  : A3: Making directory
2025/02/07 03:20:01 INFO  : A3/B3: Making directory
2025/02/07 03:20:03 INFO  : A3/B3/C4: Making directory
2025/02/07 03:20:11 INFO  : A1/two.rclone_chunk.001_as6qj9: Moved (server-side) to: A1/two
2025/02/07 03:20:14 DEBUG : removing 1 level 3 directories
2025/02/07 03:20:14 INFO  : A3/B3/C4: Removing directory
2025/02/07 03:20:21 DEBUG : removing 2 level 3 directories
2025/02/07 03:20:21 INFO  : A1/B2/C2: Removing directory
2025/02/07 03:20:21 INFO  : A1/B1/C3: Removing directory
2025/02/07 03:20:23 DEBUG : removing 2 level 2 directories
2025/02/07 03:20:23 INFO  : A3/B3: Removing directory
2025/02/07 03:20:23 INFO  : A1/B2: Removing directory
2025/02/07 03:20:24 DEBUG : removing 2 level 1 directories
2025/02/07 03:20:24 INFO  : A3: Removing directory
2025/02/07 03:20:24 INFO  : A2: Removing directory
2025/02/07 03:20:38 DEBUG : removing 1 level 3 directories
2025/02/07 03:20:38 INFO  : A1/B1/C1: Removing directory
2025/02/07 03:20:39 DEBUG : removing 1 level 2 directories
2025/02/07 03:20:39 INFO  : A1/B1: Removing directory
2025/02/07 03:20:41 DEBUG : removing 1 level 1 directories
2025/02/07 03:20:41 INFO  : A1: Removing directory
2025/02/07 03:20:42 DEBUG : removing 1 level 0 directories
2025/02/07 03:20:42 INFO  : Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo': Removing directory
2025/02/07 03:20:45 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:20:45 ERROR : : error listing: directory not found
2025/02/07 03:20:46 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:20:46 ERROR : : error listing: directory not found
--- PASS: TestRmdirsNoLeaveRoot (65.24s)
=== RUN   TestRmdirsLeaveRoot
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:20:47 DEBUG : box root 'rclone-test-paxodec6gefo': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/02/07 03:20:48 INFO  : A1: Making directory
2025/02/07 03:20:49 INFO  : A1/B1: Making directory
2025/02/07 03:20:51 INFO  : A1/B1/C1: Making directory
2025/02/07 03:20:57 DEBUG : removing 1 level 3 directories
2025/02/07 03:20:57 INFO  : A1/B1/C1: Removing directory
2025/02/07 03:20:59 DEBUG : removing 1 level 2 directories
2025/02/07 03:20:59 INFO  : A1/B1: Removing directory
--- PASS: TestRmdirsLeaveRoot (19.38s)
=== RUN   TestRmdirsWithFilter
    run.go:180: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-paxodec6gefo'", Local "Local file system at /tmp/rclone1667611889", Modify Window "1s"
2025/02/07 03:21:05 INFO  : A1: Making directory
2025/02/07 03:21:07 INFO  : A1/B1: Making directory
panic: test timed out after 1h0m0s
running tests:
	TestRmdirsWithFilter (3s)

goroutine 8947 [running]:
testing.(*M).startAlarm.func1()
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:2366 +0x385
created by time.goFunc
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/time/sleep.go:177 +0x2d

goroutine 1 [chan receive]:
testing.(*T).Run(0xc000104000, {0x25847cb?, 0x0?}, 0x26a7570)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:1750 +0x3ab
testing.runTests.func1(0xc000104000)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:2161 +0x37
testing.tRunner(0xc000104000, 0xc000a87c00)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:1689 +0xfb
testing.runTests(0xc000013848, {0x3c3a5a0, 0x6c, 0x6c}, {0x1?, 0xedf376514?, 0x3c4eae0?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:2159 +0x445
testing.(*M).Run(0xc0008501e0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:2027 +0x68b
github.com/rclone/rclone/fstest.TestMain(0xc0008501e0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:69 +0xa5
github.com/rclone/rclone/fs/operations_test.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations_test.go:61
main.main()
	_testmain.go:265 +0x196

goroutine 36 [syscall, 60 minutes]:
os/signal.signal_recv()
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/runtime/sigqueue.go:152 +0x29
os/signal.loop()
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 1
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/os/signal/signal.go:151 +0x1f

goroutine 37 [chan receive, 60 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 1
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 640 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 631
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 8926 [select]:
net/http.(*http2ClientConn).RoundTrip(0xc0004b8f00, 0xc000d05c20)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:8323 +0x434
net/http.(*http2Transport).RoundTripOpt(0xc0007933b0, 0xc000d05c20, {0xd0?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:7591 +0x1b1
net/http.(*http2Transport).RoundTrip(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:7540
net/http.http2noDialH2RoundTripper.RoundTrip({0xc00036a640?}, 0xc000d05c20?)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:10167 +0x1a
net/http.(*Transport).roundTrip(0xc00036a640, 0xc000d05b00)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/transport.go:553 +0x39c
net/http.(*Transport).RoundTrip(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/roundtrip.go:17
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc000349420, 0xc000d05b00)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:352 +0x345
golang.org/x/oauth2.(*Transport).RoundTrip(0xc000551d60, 0xc000d059e0)
	/home/rclone/go/pkg/mod/golang.org/x/oauth2@v0.25.0/transport.go:55 +0x3de
net/http.send(0xc000d059e0, {0x296ac80, 0xc000551d60}, {0xc000705001?, 0x41cc25?, 0x0?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/client.go:259 +0x5e4
net/http.(*Client).send(0xc0003dd170, 0xc000d059e0, {0x413fdb?, 0x1?, 0x0?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/client.go:180 +0x98
net/http.(*Client).do(0xc0003dd170, 0xc000d059e0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/client.go:724 +0x8dc
net/http.(*Client).Do(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/client.go:590
github.com/rclone/rclone/lib/rest.(*Client).Call(0xc0004b4640, {0x298dd40, 0xc000d19e60}, 0xc000705798)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:356 +0xd67
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc0004b4640, {0x298dd40, 0xc000d19e60}, 0xc0008d5540?, {0x1f69b20?, 0xc000d13580?}, {0x1fb2720, 0xc000a38500}, 0x40c7cb?, 0x26a8728, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:553 +0x3f2
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:496
github.com/rclone/rclone/backend/box.(*Fs).CreateDir.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:618 +0x8d
github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0x50?)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:88 +0x32
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00084c480, 0xc000ce2320, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x7c
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc00084c480, 0xc000ce2320)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x92
github.com/rclone/rclone/backend/box.(*Fs).CreateDir(0xc00055a6c0, {0x298dd40, 0xc000d19e60}, {0xc000a6fd90, 0xc}, {0x255621c, 0x2})
	/home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:617 +0x39d
github.com/rclone/rclone/lib/dircache.(*DirCache)._findDir(0xc000793290, {0x298dd40, 0xc000d19e60}, {0x2556219, 0x5}, 0x1)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:242 +0x173
github.com/rclone/rclone/lib/dircache.(*DirCache).FindDir(0xc000793290, {0x298dd40, 0xc000d19e60}, {0x2556219, 0x5}, 0x1)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:205 +0x152
github.com/rclone/rclone/backend/box.(*Fs).Mkdir(0xc0004e4000?, {0x298dd40?, 0xc000d19e60?}, {0x2556219?, 0x0?})
	/home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:873 +0x2f
github.com/rclone/rclone/backend/chunker.(*Fs).Mkdir(0xc0004e4000, {0x298dd40, 0xc000d19e60}, {0x2556219, 0x5})
	/home/rclone/go/src/github.com/rclone/rclone/backend/chunker/chunker.go:1584 +0xbb
github.com/rclone/rclone/fs/operations.Mkdir({0x298dd40, 0xc000d19e60}, {0x29a0f78, 0xc0004e4000}, {0x2556219, 0x5})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1054 +0x109
github.com/rclone/rclone/fs/operations_test.TestRmdirsWithFilter(0xc0009e6000)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations_test.go:786 +0x21f
testing.tRunner(0xc0009e6000, 0x26a7570)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:1689 +0xfb
created by testing.(*T).Run in goroutine 1
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/testing/testing.go:1742 +0x390

goroutine 2736 [chan receive, 48 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 1251 [chan receive (nil chan), 56 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1242
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 274 [chan receive (nil chan), 60 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 265
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 2878 [chan receive, 48 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 693 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 684
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 829 [chan receive (nil chan), 58 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 820
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 226 [chan receive (nil chan), 60 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 217
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 580 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 571
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 178 [chan receive (nil chan), 60 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 169
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 3346 [chan receive, 46 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 1164 [chan receive (nil chan), 56 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1155
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 1062 [chan receive (nil chan), 58 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1005
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 471 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 254
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 1150 [chan receive (nil chan), 56 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1141
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 2438 [chan receive, 50 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 338 [chan receive (nil chan), 60 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 313
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 391 [chan receive (nil chan), 60 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 382
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 3112 [chan receive, 46 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 432 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 423
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 1233 [chan receive (nil chan), 56 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1224
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 2562 [chan receive, 50 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 1320 [chan receive (nil chan), 56 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1263
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 536 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 463
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 1109 [chan receive (nil chan), 56 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 1052
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 888 [chan receive (nil chan), 58 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 799
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 748 [chan receive (nil chan), 59 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 739
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 923 [chan receive (nil chan), 58 minutes]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:211 +0x3c
created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 914
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:209 +0x378

goroutine 8568 [IO wait]:
internal/poll.runtime_pollWait(0x7f12bb5af620, 0x72)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/runtime/netpoll.go:345 +0x85
internal/poll.(*pollDesc).wait(0xc000c16800?, 0xc000b30000?, 0x0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000c16800, {0xc000b30000, 0x1000, 0x1000})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000c16800, {0xc000b30000?, 0xc000bbc838?, 0x41cc25?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00078c2e8, {0xc000b30000?, 0x7f12b9b22e58?, 0xc0008a2a38?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/net.go:179 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000b5a5b8, {0xc000b30000?, 0x4bb88f?, 0xbb5af620?})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x2c
crypto/tls.(*atLeastReader).Read(0xc0008a2a38, {0xc000b30000?, 0x0?, 0xc0008a2a38?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:806 +0x3b
bytes.(*Buffer).ReadFrom(0xc0007c3430, {0x2968de0, 0xc0008a2a38})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0007c3188, {0x7f12b920dd58, 0xc000b5a5b8}, 0xc000bbc960?)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:828 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc0007c3188, 0x0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:626 +0x3cf
crypto/tls.(*Conn).readRecord(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:588
crypto/tls.(*Conn).Read(0xc0007c3188, {0xc000924000, 0x1000, 0x11?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:1370 +0x156
bufio.(*Reader).Read(0xc000ad3380, {0xc000174740, 0x9, 0x7f938e?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/bufio/bufio.go:241 +0x197
io.ReadAtLeast({0x2967780, 0xc000ad3380}, {0xc000174740, 0x9, 0x9}, 0x9)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/io/io.go:335 +0x90
io.ReadFull(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/io/io.go:354
net/http.http2readFrameHeader({0xc000174740, 0x9, 0x7b8772?}, {0x2967780?, 0xc000ad3380?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:1638 +0x65
net/http.(*http2Framer).ReadFrame(0xc000174700)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:1902 +0x85
net/http.(*http2clientConnReadLoop).run(0xc000bbcfa8)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:9303 +0x12c
net/http.(*http2ClientConn).readLoop(0xc0008b8600)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:9198 +0x65
created by net/http.(*http2Transport).newClientConn in goroutine 8567
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:7848 +0xca6

goroutine 2662 [chan receive, 50 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 3446 [chan receive, 44 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 3195 [chan receive, 46 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 3002 [chan receive, 48 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 2437
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 8285 [chan receive, 3 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 8284
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xab

goroutine 3661 [IO wait]:
internal/poll.runtime_pollWait(0x7f12bb5aed68, 0x72)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/runtime/netpoll.go:345 +0x85
internal/poll.(*pollDesc).wait(0xc0006c9200?, 0xc0006e5000?, 0x0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0006c9200, {0xc0006e5000, 0x1000, 0x1000})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc0006c9200, {0xc0006e5000?, 0xc000bb8838?, 0x41cc25?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc000a38130, {0xc0006e5000?, 0x7f12bb5dd538?, 0xc000633290?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/net.go:179 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc00046ecd8, {0xc0006e5000?, 0x4bb88f?, 0xbb5aed68?})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x2c
crypto/tls.(*atLeastReader).Read(0xc000633290, {0xc0006e5000?, 0x0?, 0xc000633290?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:806 +0x3b
bytes.(*Buffer).ReadFrom(0xc00079b7b0, {0x2968de0, 0xc000633290})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc00079b508, {0x7f12b920dd58, 0xc00046ecd8}, 0xc000bb8960?)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:828 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc00079b508, 0x0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:626 +0x3cf
crypto/tls.(*Conn).readRecord(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:588
crypto/tls.(*Conn).Read(0xc00079b508, {0xc0007e7000, 0x1000, 0x11?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/crypto/tls/conn.go:1370 +0x156
bufio.(*Reader).Read(0xc000cbfc20, {0xc000c104a0, 0x9, 0x7f938e?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/bufio/bufio.go:241 +0x197
io.ReadAtLeast({0x2967780, 0xc000cbfc20}, {0xc000c104a0, 0x9, 0x9}, 0x9)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/io/io.go:335 +0x90
io.ReadFull(...)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/io/io.go:354
net/http.http2readFrameHeader({0xc000c104a0, 0x9, 0x7b8772?}, {0x2967780?, 0xc000cbfc20?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:1638 +0x65
net/http.(*http2Framer).ReadFrame(0xc000c10460)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:1902 +0x85
net/http.(*http2clientConnReadLoop).run(0xc000bb8fa8)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:9303 +0x12c
net/http.(*http2ClientConn).readLoop(0xc0004b8f00)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:9198 +0x65
created by net/http.(*http2Transport).newClientConn in goroutine 3660
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:7848 +0xca6

goroutine 8912 [select]:
net/http.(*http2clientStream).writeRequest(0xc000729080, 0xc000d05c20)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:8491 +0xacc
net/http.(*http2clientStream).doRequest(0xc000729080, 0xc00046f098?)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:8353 +0x18
created by net/http.(*http2ClientConn).RoundTrip in goroutine 8926
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.0.linux-amd64/src/net/http/h2_bundle.go:8259 +0x2ed
"./operations.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bBox: -verbose -size-limit 1024" - Finished ERROR in 1h0m3.504388486s (try 1/5): exit status 2: Failed []