"./operations.test -test.v -test.timeout 1h0m0s -remote TestCompressDrive: -verbose" - Starting (try 1/5) 2022/01/09 06:19:56 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8" 2022/01/09 06:19:56 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/01/09 06:19:57 DEBUG : Creating backend with remote "/tmp/rclone1710334109" === RUN TestDoMultiThreadCopy --- PASS: TestDoMultiThreadCopy (0.00s) === RUN TestMultithreadCalculateChunks === RUN TestMultithreadCalculateChunks/{size:1_streams:10_wantPartSize:65536_wantStreams:1} === RUN TestMultithreadCalculateChunks/{size:1048576_streams:1_wantPartSize:1048576_wantStreams:1} === RUN TestMultithreadCalculateChunks/{size:1048576_streams:2_wantPartSize:524288_wantStreams:2} === RUN TestMultithreadCalculateChunks/{size:1048577_streams:2_wantPartSize:589824_wantStreams:2} === RUN TestMultithreadCalculateChunks/{size:1048575_streams:2_wantPartSize:524288_wantStreams:2} --- PASS: TestMultithreadCalculateChunks (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1_streams:10_wantPartSize:65536_wantStreams:1} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048576_streams:1_wantPartSize:1048576_wantStreams:1} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048576_streams:2_wantPartSize:524288_wantStreams:2} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048577_streams:2_wantPartSize:589824_wantStreams:2} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048575_streams:2_wantPartSize:524288_wantStreams:2} (0.00s) === RUN TestMultithreadCopy run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" === RUN TestMultithreadCopy/{size:131071_streams:2} 2022/01/09 06:20:05 DEBUG : file1: Starting multi-thread copy with 2 parts of size 64Ki 2022/01/09 06:20:05 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131071) size 63.999Ki starting 2022/01/09 06:20:05 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64Ki starting 2022/01/09 06:20:05 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.RangeSeek from -1 to 10 length -1 2022/01/09 06:20:05 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:05 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.openRange at 0 length 262144 2022/01/09 06:20:05 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:05 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.openRange at 10 length 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 4106 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 8202 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 12298 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 4096 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 8192 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 12288 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 16384 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 20480 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 16394 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 20490 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 24576 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 24586 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 28672 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 28682 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 32768 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 32778 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 36864 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 36874 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 40970 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 40960 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 45056 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 45066 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 49152 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 53248 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 49162 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 53258 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 57344 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 57354 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 61440 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 65536 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 61450 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 65546 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 69632 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 73728 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 69642 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 77824 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 73738 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64Ki finished 2022/01/09 06:20:06 DEBUG : file1.__8BAAAAAAA.gz: ChunkedReader.Read at 77834 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:06 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131071) size 63.999Ki finished 2022/01/09 06:20:06 DEBUG : file1: Finished multi-thread copy with 2 parts of size 64Ki === RUN TestMultithreadCopy/{size:131072_streams:2} 2022/01/09 06:20:14 DEBUG : file1: Starting multi-thread copy with 2 parts of size 64Ki 2022/01/09 06:20:14 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131072) size 64Ki starting 2022/01/09 06:20:14 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64Ki starting 2022/01/09 06:20:14 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.RangeSeek from -1 to 10 length -1 2022/01/09 06:20:14 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:14 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.openRange at 0 length 262144 2022/01/09 06:20:14 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:14 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.openRange at 10 length 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 4096 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 8192 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 12288 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 16384 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 20480 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 24576 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 28672 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 32768 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 36864 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 40960 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 45056 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 49152 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 53248 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 57344 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 61440 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 65536 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 69632 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 73728 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 77824 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64Ki finished 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 4106 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 8202 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 12298 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 16394 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 20490 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 24586 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 28682 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 32778 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 36874 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 40970 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 45066 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 49162 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 53258 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 57354 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 61450 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 65546 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 69642 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 73738 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1.AAACAAAAAAA.gz: ChunkedReader.Read at 77834 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:15 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131072) size 64Ki finished 2022/01/09 06:20:15 DEBUG : file1: Finished multi-thread copy with 2 parts of size 64Ki === RUN TestMultithreadCopy/{size:131073_streams:2} 2022/01/09 06:20:24 DEBUG : file1: Starting multi-thread copy with 2 parts of size 128Ki 2022/01/09 06:20:24 DEBUG : file1: multi-thread copy: stream 2/2 (131072-131073) size 1 starting 2022/01/09 06:20:24 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.RangeSeek from -1 to 10 length -1 2022/01/09 06:20:24 DEBUG : file1: multi-thread copy: stream 1/2 (0-131072) size 128Ki starting 2022/01/09 06:20:24 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:24 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.openRange at 10 length 262144 2022/01/09 06:20:24 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:24 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.openRange at 0 length 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 4096 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 8192 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 12288 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 16384 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 20480 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 24576 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 28672 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 32768 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 36864 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 40960 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 45056 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 49152 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 53248 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 57344 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 61440 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 65536 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 69632 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 73728 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 77824 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:20:25 DEBUG : file1: multi-thread copy: stream 1/2 (0-131072) size 128Ki finished 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 4106 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 8202 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 12298 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 16394 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 20490 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 24586 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 28682 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 32778 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 36874 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 40970 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 45066 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 49162 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 53258 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 57354 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 61450 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 65546 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 69642 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 73738 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1.AQACAAAAAAA.gz: ChunkedReader.Read at 77834 length 4096 chunkOffset 10 chunkSize 262144 2022/01/09 06:20:26 DEBUG : file1: multi-thread copy: stream 2/2 (131072-131073) size 1 finished 2022/01/09 06:20:26 DEBUG : file1: Finished multi-thread copy with 2 parts of size 128Ki --- PASS: TestMultithreadCopy (30.80s) --- PASS: TestMultithreadCopy/{size:131071_streams:2} (8.47s) --- PASS: TestMultithreadCopy/{size:131072_streams:2} (9.54s) --- PASS: TestMultithreadCopy/{size:131073_streams:2} (10.56s) === RUN TestSizeDiffers --- PASS: TestSizeDiffers (0.00s) === RUN TestReOpen === RUN TestReOpen/Seek === RUN TestReOpen/Seek/Basics === RUN TestReOpen/Seek/ErrorAtStart === RUN TestReOpen/Seek/WithErrors 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Seek/TooManyErrors 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2022/01/09 06:20:28 DEBUG : potato: Reopen failed after 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/Range === RUN TestReOpen/Range/Basics === RUN TestReOpen/Range/ErrorAtStart === RUN TestReOpen/Range/WithErrors 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Range/TooManyErrors 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2022/01/09 06:20:28 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2022/01/09 06:20:28 DEBUG : potato: Reopen failed after 6 bytes read: failed to reopen: too many retries --- PASS: TestReOpen (0.00s) --- PASS: TestReOpen/Seek (0.00s) --- PASS: TestReOpen/Seek/Basics (0.00s) --- PASS: TestReOpen/Seek/ErrorAtStart (0.00s) --- PASS: TestReOpen/Seek/WithErrors (0.00s) --- PASS: TestReOpen/Seek/TooManyErrors (0.00s) --- PASS: TestReOpen/Range (0.00s) --- PASS: TestReOpen/Range/Basics (0.00s) --- PASS: TestReOpen/Range/ErrorAtStart (0.00s) --- PASS: TestReOpen/Range/WithErrors (0.00s) --- PASS: TestReOpen/Range/TooManyErrors (0.00s) === RUN TestCheck run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" === RUN TestCheck/1 === RUN TestCheck/2 === RUN TestCheck/3 === RUN TestCheck/4 === RUN TestCheck/5 === RUN TestCheck/6 === RUN TestCheck/7 --- PASS: TestCheck (45.54s) --- PASS: TestCheck/1 (1.60s) --- PASS: TestCheck/2 (2.21s) --- PASS: TestCheck/3 (1.93s) --- PASS: TestCheck/4 (1.77s) --- PASS: TestCheck/5 (1.82s) --- PASS: TestCheck/6 (1.43s) --- PASS: TestCheck/7 (1.32s) === RUN TestCheckFsError 2022/01/09 06:21:14 DEBUG : Creating backend with remote "non-existent" 2022/01/09 06:21:14 DEBUG : Creating backend with remote "non-existent" 2022/01/09 06:21:14 DEBUG : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: Waiting for checks to finish 2022/01/09 06:21:14 ERROR : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: error reading source root directory: directory not found 2022/01/09 06:21:14 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: 2 differences found 2022/01/09 06:21:14 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: 2 errors while checking --- PASS: TestCheckFsError (0.00s) === RUN TestCheckDownload run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" === RUN TestCheckDownload/1 === RUN TestCheckDownload/2 === RUN TestCheckDownload/3 === RUN TestCheckDownload/4 === RUN TestCheckDownload/5 === RUN TestCheckDownload/6 === RUN TestCheckDownload/7 --- PASS: TestCheckDownload (45.52s) --- PASS: TestCheckDownload/1 (2.19s) --- PASS: TestCheckDownload/2 (2.07s) --- PASS: TestCheckDownload/3 (2.17s) --- PASS: TestCheckDownload/4 (2.14s) --- PASS: TestCheckDownload/5 (2.02s) --- PASS: TestCheckDownload/6 (1.85s) --- PASS: TestCheckDownload/7 (1.72s) === RUN TestCheckSizeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" === RUN TestCheckSizeOnly/1 === RUN TestCheckSizeOnly/2 === RUN TestCheckSizeOnly/3 === RUN TestCheckSizeOnly/4 === RUN TestCheckSizeOnly/5 === RUN TestCheckSizeOnly/6 === RUN TestCheckSizeOnly/7 --- PASS: TestCheckSizeOnly (33.31s) --- PASS: TestCheckSizeOnly/1 (0.28s) --- PASS: TestCheckSizeOnly/2 (0.31s) --- PASS: TestCheckSizeOnly/3 (0.29s) --- PASS: TestCheckSizeOnly/4 (0.29s) --- PASS: TestCheckSizeOnly/5 (0.29s) --- PASS: TestCheckSizeOnly/6 (0.30s) --- PASS: TestCheckSizeOnly/7 (0.36s) === RUN TestCheckEqualReaders --- PASS: TestCheckEqualReaders (0.00s) === RUN TestParseSumFile run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:22:37 DEBUG : test.sum.UQAAAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:22:37 DEBUG : test.sum.UQAAAAAAAAA.gz: ChunkedReader.openRange at 0 length 262144 2022/01/09 06:22:38 NOTICE: test.sum: improperly formatted checksum line 4 2022/01/09 06:22:38 NOTICE: test.sum: improperly formatted checksum line 5 2022/01/09 06:22:38 NOTICE: test.sum: improperly formatted checksum line 6 2022/01/09 06:22:38 NOTICE: test.sum: 2 warning(s) suppressed... 2022/01/09 06:22:44 DEBUG : test.sum.WgAAAAAAAAA.gz: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 262144 2022/01/09 06:22:44 DEBUG : test.sum.WgAAAAAAAAA.gz: ChunkedReader.openRange at 0 length 262144 2022/01/09 06:22:45 NOTICE: test.sum: improperly formatted checksum line 4 2022/01/09 06:22:45 NOTICE: test.sum: improperly formatted checksum line 5 2022/01/09 06:22:45 NOTICE: test.sum: improperly formatted checksum line 6 2022/01/09 06:22:45 NOTICE: test.sum: 2 warning(s) suppressed... --- PASS: TestParseSumFile (14.86s) === RUN TestCheckSum run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:22:47 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8/data" === RUN TestCheckSum/subtest1 === RUN TestCheckSum/subtest2 === RUN TestCheckSum/subtest3 === RUN TestCheckSum/subtest4 === RUN TestCheckSum/subtest5 === RUN TestCheckSum/subtest6 === RUN TestCheckSum/subtest7 2022/01/09 06:24:35 DEBUG : data: Rmdir: contains trashed file: "potato.json" 2022/01/09 06:24:35 DEBUG : data: Rmdir: contains trashed file: "potato.DwAAAAAAAAA.gz" 2022/01/09 06:24:35 DEBUG : data: Rmdir: contains trashed file: "banana.DQAAAAAAAAA.gz" 2022/01/09 06:24:35 DEBUG : data: Rmdir: contains trashed file: "banana.json" --- PASS: TestCheckSum (108.93s) --- PASS: TestCheckSum/subtest1 (4.13s) --- PASS: TestCheckSum/subtest2 (2.93s) --- PASS: TestCheckSum/subtest3 (4.35s) --- PASS: TestCheckSum/subtest4 (4.34s) --- PASS: TestCheckSum/subtest5 (4.41s) --- PASS: TestCheckSum/subtest6 (4.42s) --- PASS: TestCheckSum/subtest7 (4.72s) === RUN TestCheckSumDownload run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:24:36 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8/data" === RUN TestCheckSumDownload/subtest1 === RUN TestCheckSumDownload/subtest2 === RUN TestCheckSumDownload/subtest3 === RUN TestCheckSumDownload/subtest4 === RUN TestCheckSumDownload/subtest5 === RUN TestCheckSumDownload/subtest6 === RUN TestCheckSumDownload/subtest7 2022/01/09 06:26:23 DEBUG : data: Rmdir: contains trashed file: "potato.DwAAAAAAAAA.gz" 2022/01/09 06:26:23 DEBUG : data: Rmdir: contains trashed file: "potato.json" 2022/01/09 06:26:23 DEBUG : data: Rmdir: contains trashed file: "banana.json" 2022/01/09 06:26:23 DEBUG : data: Rmdir: contains trashed file: "banana.DQAAAAAAAAA.gz" --- PASS: TestCheckSumDownload (107.95s) --- PASS: TestCheckSumDownload/subtest1 (4.96s) --- PASS: TestCheckSumDownload/subtest2 (4.40s) --- PASS: TestCheckSumDownload/subtest3 (4.69s) --- PASS: TestCheckSumDownload/subtest4 (3.88s) --- PASS: TestCheckSumDownload/subtest5 (3.90s) --- PASS: TestCheckSumDownload/subtest6 (3.77s) --- PASS: TestCheckSumDownload/subtest7 (3.76s) === RUN TestDeduplicateInteractive run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateInteractive (0.52s) === RUN TestDeduplicateSkip run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateSkip (0.54s) === RUN TestDeduplicateSizeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateSizeOnly (0.64s) === RUN TestDeduplicateFirst run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateFirst (0.59s) === RUN TestDeduplicateNewest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateNewest (0.52s) === RUN TestDeduplicateNewestByHash run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:26:46 INFO : Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8: Looking for duplicate md5 hashes using newest mode. 2022/01/09 06:26:50 NOTICE: 8627ca66490ea2cc0bccdc9cb4540457: Found 3 files with duplicate md5 hashes 2022/01/09 06:26:51 INFO : one: Deleted 2022/01/09 06:26:53 INFO : also/one: Deleted 2022/01/09 06:26:53 NOTICE: 8627ca66490ea2cc0bccdc9cb4540457: Deleted 2 extra copies 2022/01/09 06:26:59 DEBUG : also: Rmdir: contains trashed file: "one.ZAAAAAAAAAA.gz" 2022/01/09 06:26:59 DEBUG : also: Rmdir: contains trashed file: "one.json" --- PASS: TestDeduplicateNewestByHash (32.85s) === RUN TestDeduplicateOldest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateOldest (0.53s) === RUN TestDeduplicateLargest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateLargest (0.59s) === RUN TestDeduplicateSmallest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateSmallest (0.52s) === RUN TestDeduplicateRename run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" dedupe_test.go:24: Can't test deduplicate - no duplicate files possible --- SKIP: TestDeduplicateRename (0.57s) === RUN TestMergeDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:27:16 INFO : dupe2: merging "two.txt.DwAAAAAAAAA.gz" 2022/01/09 06:27:17 INFO : dupe2: merging "two.txt.json" 2022/01/09 06:27:17 INFO : dupe2: removing empty directory 2022/01/09 06:27:18 INFO : dupe3: merging "three.txt.EwAAAAAAAAA.gz" 2022/01/09 06:27:19 INFO : dupe3: merging "three.txt.json" 2022/01/09 06:27:20 INFO : dupe3: removing empty directory 2022/01/09 06:27:30 DEBUG : dupe1: Rmdir: contains trashed file: "three.txt.EwAAAAAAAAA.gz" 2022/01/09 06:27:30 DEBUG : dupe1: Rmdir: contains trashed file: "three.txt.json" 2022/01/09 06:27:30 DEBUG : dupe1: Rmdir: contains trashed file: "two.txt.DwAAAAAAAAA.gz" 2022/01/09 06:27:30 DEBUG : dupe1: Rmdir: contains trashed file: "two.txt.json" 2022/01/09 06:27:30 DEBUG : dupe1: Rmdir: contains trashed file: "one.txt.bin" 2022/01/09 06:27:30 DEBUG : dupe1: Rmdir: contains trashed file: "one.txt.json" --- PASS: TestMergeDirs (28.78s) === RUN TestListDirSorted run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:28:05 DEBUG : a.txt: Excluded 2022/01/09 06:28:05 DEBUG : sub dir/hello world2: Excluded 2022/01/09 06:28:05 DEBUG : sub dir/hello world: Excluded 2022/01/09 06:28:07 DEBUG : sub dir/ignore dir: Excluded 2022/01/09 06:28:07 DEBUG : sub dir/hello world2: Excluded 2022/01/09 06:28:07 DEBUG : sub dir/hello world: Excluded 2022/01/09 06:28:07 DEBUG : sub dir/ignore dir: Excluded 2022/01/09 06:28:20 DEBUG : sub dir/sub sub dir: Rmdir: contains trashed file: "hello world3.bin" 2022/01/09 06:28:20 DEBUG : sub dir/sub sub dir: Rmdir: contains trashed file: "hello world3.json" 2022/01/09 06:28:21 DEBUG : sub dir/ignore dir: Rmdir: contains trashed file: "should be ignored.bin" 2022/01/09 06:28:21 DEBUG : sub dir/ignore dir: Rmdir: contains trashed file: ".ignore.json" 2022/01/09 06:28:21 DEBUG : sub dir/ignore dir: Rmdir: contains trashed file: ".ignore.bin" 2022/01/09 06:28:21 DEBUG : sub dir/ignore dir: Rmdir: contains trashed file: "should be ignored.json" 2022/01/09 06:28:22 DEBUG : sub dir: Rmdir: contains trashed file: "sub sub dir" 2022/01/09 06:28:22 DEBUG : sub dir: Rmdir: contains trashed file: "ignore dir" 2022/01/09 06:28:22 DEBUG : sub dir: Rmdir: contains trashed file: "hello world2.bin" 2022/01/09 06:28:22 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/01/09 06:28:22 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/01/09 06:28:22 DEBUG : sub dir: Rmdir: contains trashed file: "hello world2.json" --- PASS: TestListDirSorted (51.82s) === RUN TestListJSON run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" === 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 2022/01/09 06:28:47 DEBUG : sub: Rmdir: contains trashed file: "file2.json" 2022/01/09 06:28:47 DEBUG : sub: Rmdir: contains trashed file: "file2.bin" --- PASS: TestListJSON (25.58s) --- PASS: TestListJSON/Default (1.37s) --- PASS: TestListJSON/FilesOnly (1.31s) --- PASS: TestListJSON/DirsOnly (0.29s) --- PASS: TestListJSON/Recurse (2.48s) --- PASS: TestListJSON/SubDir (1.16s) --- PASS: TestListJSON/NoModTime (1.15s) --- PASS: TestListJSON/NoMimeType (0.28s) --- PASS: TestListJSON/ShowHash (1.10s) --- PASS: TestListJSON/HashTypes (1.10s) === RUN TestStatJSON run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" === RUN TestStatJSON/Root === RUN TestStatJSON/RootFilesOnly === RUN TestStatJSON/RootDirsOnly === RUN TestStatJSON/Dir === 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 2022/01/09 06:29:04 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8/notfound" 2022/01/09 06:29:04 DEBUG : Config file has changed externaly - reloading 2022/01/09 06:29:11 DEBUG : sub: Rmdir: contains trashed file: "file2.bin" 2022/01/09 06:29:11 DEBUG : sub: Rmdir: contains trashed file: "file2.json" --- PASS: TestStatJSON (23.55s) --- PASS: TestStatJSON/Root (0.31s) --- PASS: TestStatJSON/RootFilesOnly (0.00s) --- PASS: TestStatJSON/RootDirsOnly (0.29s) --- PASS: TestStatJSON/Dir (0.56s) --- PASS: TestStatJSON/File (1.11s) --- PASS: TestStatJSON/NotFound (0.56s) --- PASS: TestStatJSON/DirFilesOnly (0.34s) --- PASS: TestStatJSON/FileFilesOnly (1.04s) --- PASS: TestStatJSON/NotFoundFilesOnly (0.28s) --- PASS: TestStatJSON/DirDirsOnly (0.29s) --- PASS: TestStatJSON/FileDirsOnly (0.28s) --- PASS: TestStatJSON/NotFoundDirsOnly (0.31s) --- PASS: TestStatJSON/RootNotFound (2.77s) === RUN TestMkdir run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:29:12 DEBUG : Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8: Making directory 2022/01/09 06:29:12 DEBUG : Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8: Making directory --- PASS: TestMkdir (0.87s) === RUN TestLsd run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:29:21 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/01/09 06:29:21 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestLsd (9.66s) === RUN TestLs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:29:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/09 06:29:34 DEBUG : pacer: Rate limited, increasing sleep to 1.79177875s 2022/01/09 06:29:34 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestLs (14.54s) === RUN TestLsWithFilesFrom run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:29:46 DEBUG : empty space: Excluded --- PASS: TestLsWithFilesFrom (14.18s) === RUN TestLsLong run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" --- PASS: TestLsLong (13.15s) === RUN TestHashSums run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-vazivok3vuhusol0jadikuf8", Local "Local file system at /tmp/rclone1710334109", Modify Window "1ms" 2022/01/09 06:30:06 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/09 06:30:06 DEBUG : pacer: Rate limited, increasing sleep to 1.961477696s 2022/01/09 06:30:07 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/09 06:30:07 DEBUG : pacer: Rate limited, increasing sleep to 2.581561237s 2022/01/09 06:30:09 DEBUG : pacer: Reducing sleep to 0s run.go:126: removing file "potato2" failed - try 1/3: object not found run.go:126: removing file "potato2" failed - try 2/3: object not found run.go:126: removing file "potato2" failed - try 3/3: object not found run.go:129: removing file "potato2" failed: object not found fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 run.go:174 run.go:376 panic.go:1038 panic.go:221 signal_unix.go:735 compress.go:629 compress.go:658 compress.go:687 run.go:277 run.go:294 run.go:305 operations_test.go:189 Error: Should be true Test: TestHashSums Messages: listing wrong, want got potato2 (60) fstest.go:192: Error Trace: fstest.go:192 fstest.go:309 fstest.go:339 run.go:174 run.go:376 panic.go:1038 panic.go:221 signal_unix.go:735 compress.go:629 compress.go:658 compress.go:687 run.go:277 run.go:294 run.go:305 operations_test.go:189 Error: Should be true Test: TestHashSums Messages: Unexpected file "potato2" --- FAIL: TestHashSums (18.98s) panic: runtime error: invalid memory address or nil pointer dereference [recovered] panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0xb76ca6] goroutine 3668 [running]: testing.tRunner.func1.2({0x16268e0, 0x28bf050}) /usr/local/go/src/testing/testing.go:1209 +0x24e testing.tRunner.func1() /usr/local/go/src/testing/testing.go:1212 +0x218 panic({0x16268e0, 0x28bf050}) /usr/local/go/src/runtime/panic.go:1038 +0x215 github.com/rclone/rclone/backend/compress.(*Fs).putMetadata(0xc000178100, {0x1c7b7d0, 0xc000040058}, 0x1c7b7d0, {0x1c93440, 0xc002f4d1d0}, {0x0, 0x0, 0x0}, 0xc004bcb858) /home/rclone/go/src/github.com/rclone/rclone/backend/compress/compress.go:629 +0x226 github.com/rclone/rclone/backend/compress.(*Fs).putWithCustomFunctions(0xc000178100, {0x1c7b7d0, 0xc000040058}, {0x1c47680, 0xc004be5560}, {0x1c93440, 0xc002f4d1d0}, {0x0, 0x0, 0x0}, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/compress/compress.go:658 +0x166 github.com/rclone/rclone/backend/compress.(*Fs).Put(0xc000178100, {0x1c7b7d0, 0xc000040058}, {0x1c42ae0, 0xc000496360}, {0x1c93440, 0xc002f4d1d0}, {0x0, 0x0, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/backend/compress/compress.go:687 +0x2bd github.com/rclone/rclone/fstest.(*Run).WriteObjectTo(0xc0002e0380, {0x1c7b7d0, 0xc000040058}, {0x1caa6f8, 0xc000178100}, {0x18cec0f, 0x7}, {0x193bfa7, 0x3c}, {0x1dcd64ff, ...}, ...) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:277 +0x432 github.com/rclone/rclone/fstest.(*Run).WriteObject(...) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:294 github.com/rclone/rclone/fstest.(*Run).WriteBoth(0xc0002e0380, {0x1c7b7d0, 0xc000040058}, {0x18cec0f, 0x7}, {0x193bfa7, 0x3c}, {0x1dcd64ff, 0xeb20d7a72, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:305 +0x125 github.com/rclone/rclone/fs/operations_test.TestHashSums(0xc000853faf) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations_test.go:189 +0xf2 testing.tRunner(0xc0008c0b60, 0x1979d78) /usr/local/go/src/testing/testing.go:1259 +0x102 created by testing.(*T).Run /usr/local/go/src/testing/testing.go:1306 +0x35a "./operations.test -test.v -test.timeout 1h0m0s -remote TestCompressDrive: -verbose" - Finished ERROR in 10m27.204653095s (try 1/5): exit status 2: Failed [TestHashSums]