Sporadic 'index out of bounds' panic in tls client

[cryptocode]

Zig Version

0.11.0-dev.2477+2ee328995

Steps to Reproduce and Observed Behavior

Using the test program I received from @truemedian to test a fix for the slow TLS bug:

const std = @import("std");

pub fn main() !void {
    var gpa = std.heap.GeneralPurposeAllocator(.{.never_unmap=true, .retain_metadata=true}){};
    defer _ = gpa.deinit();

    const allocator = gpa.allocator();
    var args = std.process.args();

    _ = args.next();
    const uri = try std.Uri.parse(args.next() orelse unreachable);

    var client = std.http.Client{ .allocator = allocator };
    defer client.deinit();

    var req = try client.request(uri, .{
        .method = .GET,
    }, .{});
    defer req.deinit();

    try req.do();

    const body1 = try req.reader().readAllAlloc(std.heap.page_allocator, 8192 * 1024 * 1024);
    defer std.heap.page_allocator.free(body1);
}

zig build-exe test-https.zig

Then execute this in a loop in a shell:

./test-https https://github.com/MasterQ32/parser-toolkit/archive/master.tar.gz

Usually it works, but sporadically the program either hangs or panics with:

./test-https https://github.com/MasterQ32/parser-toolkit/archive/master.tar.gz
thread 2176140 panic: index out of bounds: index 5531, len 2922
lib/std/mem.zig:199:14: 0x10d10047e in copy__anon_7272 (test-https)
    for (dest[0..source.len], source) |*d, s|
             ^
lib/std/crypto/tls/Client.zig:1062:30: 0x10d13ff2c in readvAdvanced__anon_9441 (test-https)
            mem.copy(u8, frag[0..in], first);
                             ^
lib/std/crypto/tls/Client.zig:898:53: 0x10d13d1ef in readvAtLeast__anon_9440 (test-https)
        var amt = try c.readvAdvanced(stream, iovecs[vec_i..]);
                                                    ^
lib/std/crypto/tls/Client.zig:859:24: 0x10d13cf30 in readAtLeast__anon_9438 (test-https)
    return readvAtLeast(c, stream, &iovecs, len);
                       ^
lib/std/crypto/tls/Client.zig:864:23: 0x10d13ce72 in read__anon_9437 (test-https)
    return readAtLeast(c, stream, buffer, 1);
                      ^
lib/std/http/Client.zig:208:53: 0x10d13ccff in read (test-https)
            .tls => return conn.tls_client.read(conn.stream, buffer),
                                                    ^
lib/std/http/Client.zig:313:46: 0x10d14fcfc in readAtLeast (test-https)
                return bconn.conn.read(buffer[out_index..]);
                                             ^
lib/std/http/Client.zig:323:33: 0x10d0ed6f8 in read (test-https)
        return bconn.readAtLeast(buffer, 1);
                                ^
lib/std/http/protocol.zig:542:60: 0x10d0ec7d0 in read__anon_6343 (test-https)
                        const nread = try bconn.read(buffer[0..can_read]);
                                                           ^
lib/std/http/Client.zig:638:107: 0x10d0ee387 in transferRead (test-https)
            const amt = req.response.parser.read(&req.connection.data.buffered, buf[index..], req.response.skip) catch |err| {
                                                                                                          ^
lib/std/http/Client.zig:782:45: 0x10d104a69 in read (test-https)
                else => try req.transferRead(buffer),
                                            ^
lib/std/io/reader.zig:27:31: 0x10d21ff39 in read (test-https)
            return readFn(self.context, buffer);
                              ^
lib/std/io/reader.zig:46:49: 0x10d1061d8 in readAtLeast (test-https)
                const amt = try self.read(buffer[index..]);
                                                ^
lib/std/io/reader.zig:34:52: 0x10d0e454e in readAll (test-https)
            return readAtLeast(self, buffer, buffer.len);
                                                   ^
lib/std/io/reader.zig:80:52: 0x10d0e3ee7 in readAllArrayListAligned__anon_5764 (test-https)
                const bytes_read = try self.readAll(dest_slice);
                                                   ^
lib/std/io/reader.zig:65:48: 0x10d0e3c41 in readAllArrayList (test-https)
            return self.readAllArrayListAligned(null, array_list, max_append_size);
                                               ^
lib/std/io/reader.zig:105:38: 0x10d0e471d in readAllAlloc (test-https)
            try self.readAllArrayList(&array_list, max_size);
                                     ^
/Users/cc/projects/zigprojects/zig/test-https.zig:23:86: 0x10d0e4f86 in main (test-https)
    const body1 = try req.reader().readAllAlloc(std.heap.page_allocator, 8192 * 1024 * 1024);
                                                                                     ^
lib/std/start.zig:619:37: 0x10d0e7645 in main (test-https)
            const result = root.main() catch |err| {
                                    ^
???:?:?: 0x7ff80fc9730f in ??? (???)
???:?:?: 0x0 in ??? (???)
[1]    81814 abort      ./test-https https://github.com/MasterQ32/parser-toolkit/archive/master.tar.gz

Expected Behavior

No panic: and no hangs

Note

The response headers may vary in length for the same URL. Some responses can have different lengths of various ID fields, sometimes the response is chunked, sometimes with response-length.

Both chunked and non-chunked responses sometimes work, so that's not the issue by itself.

[andrewrk]

Now we have both http client and server, let's also gain a TLS server in addition to TLS client, and then we can add some unit testing and fuzz testing for all 4 of these APIs.

[sgwong]

zig version: 0.11.0-dev.4006+bf827d0b5
tested with current latest version. I can't reproduce this on windows for 50 loops.
It works with and without #16436 changes.

I had to changed the test code to in order to run on latest zig master.

const std = @import("std");

pub fn main() !void {
    var gpa = std.heap.GeneralPurposeAllocator(.{ .never_unmap = true, .retain_metadata = true }){};
    defer _ = gpa.deinit();
    const allocator = gpa.allocator();

    var args = try std.process.argsWithAllocator(allocator);
    defer args.deinit();

    _ = args.next();
    const uri = try std.Uri.parse(args.next() orelse unreachable);

    var client = std.http.Client{ .allocator = allocator };
    defer client.deinit();

    var req = try client.request(.GET, uri, .{ .allocator = allocator }, .{});
    defer req.deinit();

    try req.start();
    try req.wait();

    const body1 = try req.reader().readAllAlloc(std.heap.page_allocator, 8192 * 1024 * 1024);
    std.debug.print("{d} {s}\n", .{ body1.len, body1[0..10] });
    defer std.heap.page_allocator.free(body1);
}

[cryptocode]

Thanks @sgwong, same result here. Tested several URLs in a loop with no issues.

[karlseguin]

This is still an issue. The following code should eventually panic, but it can take a very long time. Might just be my imagination, but I feel if it doesn't happen in the first 5 minutes, it's best to stop and restart it.

const std = @import("std");

const net = std.net;
const tls = std.crypto.tls;

pub fn main() !void {
  var general_purpose_allocator = std.heap.GeneralPurposeAllocator(.{}){};
  const allocator = general_purpose_allocator.allocator();

  var bundle = std.crypto.Certificate.Bundle{};
  try bundle.rescan(allocator);

  const stream = try net.tcpConnectToHost(allocator, "ws-feed.exchange.coinbase.com", 443);
  var client = try tls.Client.init(stream, bundle, "ws-feed.exchange.coinbase.com");

  // Websocket Handshake.
  try client.writeAll(stream, &.{71, 69, 84, 32, 47, 32, 72, 84, 84, 80, 47, 49, 46, 49, 13, 10, 99, 111, 110, 116, 101, 110, 116, 45, 108, 101, 110, 103, 116, 104, 58, 32, 48, 13, 10, 117, 112, 103, 114, 97, 100, 101, 58, 32, 119, 101, 98, 115, 111, 99, 107, 101, 116, 13, 10, 115, 101, 99, 45, 119, 101, 98, 115, 111, 99, 107, 101, 116, 45, 118, 101, 114, 115, 105, 111, 110, 58, 32, 49, 51, 13, 10, 99, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 117, 112, 103, 114, 97, 100, 101, 13, 10, 115, 101, 99, 45, 119, 101, 98, 115, 111, 99, 107, 101, 116, 45, 107, 101, 121, 58, 32, 103, 57, 83, 108, 115, 76, 55, 50, 65, 90, 69, 66, 97, 69, 50, 99, 101, 106, 108, 43, 106, 81, 61, 61, 13, 10, 72, 111, 115, 116, 58, 32, 119, 115, 45, 102, 101, 101, 100, 46, 101, 120, 99, 104, 97, 110, 103, 101, 46, 99, 111, 105, 110, 98, 97, 115, 101, 46, 99, 111, 109, 13, 10, 13, 10});

  // This sends a subscribe message. The payload is JSON, but it's framed and masked
  // as a websocket frame. It's taken from the first example at:
  //  https://docs.cloud.coinbase.com/exchange/docs/websocket-overview
  try client.writeAll(stream, &.{129, 254, 0, 218, 38, 123, 44, 129, 93, 113, 37, 163, 82, 2, 92, 228, 4, 65, 12, 163, 85, 14, 78, 242, 69, 9, 69, 227, 67, 89, 0, 139, 47, 89, 92, 243, 73, 31, 89, 226, 82, 36, 69, 229, 85, 89, 22, 161, 125, 113, 37, 136, 47, 89, 105, 213, 110, 86, 121, 210, 98, 89, 0, 139, 47, 114, 37, 163, 99, 47, 100, 172, 99, 46, 126, 163, 44, 114, 113, 173, 44, 114, 14, 226, 78, 26, 66, 239, 67, 23, 95, 163, 28, 91, 119, 139, 47, 114, 37, 163, 74, 30, 90, 228, 74, 73, 14, 173, 44, 114, 37, 136, 4, 19, 73, 224, 84, 15, 78, 228, 71, 15, 14, 173, 44, 114, 37, 136, 93, 113, 37, 136, 47, 114, 37, 163, 72, 26, 65, 228, 4, 65, 12, 163, 82, 18, 79, 234, 67, 9, 14, 173, 44, 114, 37, 136, 47, 114, 14, 241, 84, 20, 72, 244, 69, 15, 115, 232, 66, 8, 14, 187, 6, 32, 38, 136, 47, 114, 37, 136, 47, 114, 14, 196, 114, 51, 1, 195, 114, 56, 14, 173, 44, 114, 37, 136, 47, 114, 37, 136, 4, 62, 120, 201, 11, 46, 127, 197, 4, 113, 37, 136, 47, 114, 37, 220, 44, 114, 37, 136, 91, 113, 37, 220, 44, 6});

  var buf: [512]u8 = undefined;
  while (true) {
    const n = try client.read(stream, buf[0..]);
    if (n == 0) {
      break;
    }
    std.debug.print("{s}\n", .{buf[0..n]});
  }
}

All this program does is send a websocket handshake, and then sends a framed and masked json subscribed message (from the coinbase documentation). It then just continues to read from the socket and print the output. If you run this and notice that every json message is prefixed with something like "�~�", that's the websocket framing data. The sample program doesn't try to parse the data, just print it, so that's normal.

Eventually, you get:

thread 4912299 panic: index out of bounds: index 16646, len 16645
/opt/zig/lib/std/crypto/tls/Client.zig:1233:88: 0x104d95ac3 in readvAdvanced__anon_4213 (test)
                                    c.partially_read_buffer[c.partial_ciphertext_idx..][0..msg.len],
                                                                                       ^
/opt/zig/lib/std/crypto/tls/Client.zig:928:38: 0x104d9d8ab in readvAtLeast__anon_4212 (test)
        var amt = try c.readvAdvanced(stream, iovecs[vec_i..]);
                                     ^
/opt/zig/lib/std/crypto/tls/Client.zig:889:24: 0x104d9dd37 in readAtLeast__anon_4210 (test)
    return readvAtLeast(c, stream, &iovecs, len);
                       ^
/opt/zig/lib/std/crypto/tls/Client.zig:894:23: 0x104d9de0f in read__anon_4209 (test)
    return readAtLeast(c, stream, buffer, 1);
                      ^
/tmp/test.zig:21:28: 0x104d9e227 in main (test)
  const n = try client.read(stream, buf[0..]);

[karlseguin]

I'm trying to reproduce another possible bug with the TLS client, and in doing so, I might have found a slightly more reliable way to reproduce this. It seems to happen a lot more often around network hiccups. What I did was run the above code in a docker container, and use:

docker network disconnect bridge $CONTAINER_ID
sleep 45
docker network connect bridge $CONTAINER_ID

Some time between 30-45 seconds works most reliably on my computer.

This is the Dockerfile I used:

from ubuntu:latest
run apt-get update && apt-get install -y wget xz-utils

run wget "https://ziglang.org/builds/zig-linux-aarch64-0.12.0-dev.2777+2176a73d6.tar.xz"
run tar -xJvf zig-linux-aarch64-0.12.0-dev.2777+2176a73d6.tar.xz && \
    mv /zig-linux-aarch64-0.12.0-dev.2777+2176a73d6/ /zig && \
    chmod a+x /zig && \
    rm -fr /zig-*

copy test.zig /test.zig
entrypoint ["/zig/zig", "run", "/test.zig"]

where test.zig is the above code.

[clickingbuttons]

Another stack trace crashing on line 1271 instead of 1233:

thread 167871 panic: index out of bounds: index 16762, len 16645
/home/thesm/.local/share/zvm/0.12.0-dev.2811+3cafb9655/lib/std/crypto/tls/Client.zig:1271:68: 0x11d32a0 in finishRead (stream)
        @memcpy(c.partially_read_buffer[c.partial_ciphertext_idx..][0..saved_buf.len], saved_buf);
                                                                   ^
/home/thesm/.local/share/zvm/0.12.0-dev.2811+3cafb9655/lib/std/crypto/tls/Client.zig:1092:34: 0x11cd7b6 in readvAdvanced__anon_9344 (stream)
                return finishRead(c, frag, in, vp.total);
                                 ^
/home/thesm/.local/share/zvm/0.12.0-dev.2811+3cafb9655/lib/std/crypto/tls/Client.zig:928:38: 0x11dad26 in readvAtLeast__anon_9343 (stream)
        var amt = try c.readvAdvanced(stream, iovecs[vec_i..]);
                                     ^
/home/thesm/.local/share/zvm/0.12.0-dev.2811+3cafb9655/lib/std/crypto/tls/Client.zig:889:24: 0x11db1f6 in readAtLeast__anon_9341 (stream)
    return readvAtLeast(c, stream, &iovecs, len);
                       ^
/home/thesm/.local/share/zvm/0.12.0-dev.2811+3cafb9655/lib/std/crypto/tls/Client.zig:894:23: 0x11db2c1 in read__anon_9340 (stream)
    return readAtLeast(c, stream, buffer, 1);
                      ^
/home/thesm/.cache/zig/p/1220ce168e550f8904364acd0a72f5cafd40caa08a50ba83aac50b97ba700d7bcf20/src/client.zig:290:26: 0x11db405 in read (stream)
   return tls_client.read(self.stream, buf);

I wish I could speculate where the error is, but it takes a minute to reproduce and std.tls.Client.readvAdvanced sure is gnarly...

[karlseguin]

This issue may or may not be related to another issue: reading works, but fills the buffer with garbage data (maybe it's encrypted data, I dunno). I have not been able to reproduce it reliably at all. For one, the index out of bounds happens too often. I tried to double the size of partially_read_buffer (so that I'd stop getting the index out of bounds error), but then I never saw the garbage data...maybe the larger buffer just makes it less likely to happen, or maybe it isn't related and I just got lucky, since it's so rare.

Getting out of bounds is one thing....but having it succeed but with corrupt data seems like a much worse issue.

[clickingbuttons]

I've figured out a bit more.

Crash happens after finishRead. Ciphertext from saved_buf ends up in the middle of the partially_read_buffer.

Example bad read:

[{"ev":"T","sym":"AAL","i":"3263","x":7,"p":15.2,"s":7,"c":[14,37,41],"t":1708715280204,"q":5069711,"z":3},{"ev":"T","sym":"MDT","i":"52983543451702","x":10,"p":85.735,"s":100,"t":1708715280175,"q":1902906,"z":1},{"ev":"T","sym":"IWM","i":"62879802616939","x":12,"p":200.79,"s":5,"c":[14,37,41],"t":1708715280173,"q":500957,"z":1},{"ev":"T","sym":"IWM","i":"62879802616940","x":12,"p":200.79,"s":12,"c":[14,37,41],"t":1708715280173,"q":500958,"z":1},{"ev":"T","sym":"LMND","i":"62879802617683","x":12,"p":17.74,"s":5,"c":[14,37,41],"t":1708715280174,"q":1491441,"z":1},{"ev":"T","sym":"IWM","i":"52983525487958","x":8,"p":200.79,"s":47,"c":[14,37,41],"t":1708715280173,"q":500959,"z":1},{"ev":"T","sym":"SHO","i":"52983525046085","x":18,"p":11.3,"s":100,"t":1708715280195,"q":2389821,"z":1},{"ev":"T","sym":"SHO","i":"52983525046086","x":18,"p":11.3,"s":6,"c":[37],"t":1708715280195,"q":2389822,"z":1},{"ev":"T","sym":"SHO","i":"52983525046087","x":18,"p":11.3,"s":6,"c":[37],"t":1708715280195,"q":2389823,"z":1},{"ev":"T","sym":"SHO","i":"52983525163336","x":7,"p":11.3,"s":5,"c":[14,37,41],"t":1708715280195,"q":2389824,"z":1},{"ev":"T","sym":"SHO","i":"52983525163337","x":7,"p":11.3,"s":78,"c":[37],"t":1708715280195,"q":2389825,"z":1},{"ev":"T","sym":"PANW","i":"40800","x":12,"p":282.29,"s":5,"c":[14,37,41],"t":1708715280172,"q":6095149,"z":3},{"ev":"T","sym":"PANW","i":"6303","x":21,"p":282.29,"s":5,"c":[14,37,41],"t":1708715280172,"q":6095150,"z":3},{"ev":"T","sym":"PANW","i":"14645","x":8,"p":282.3,"s":26,"c":[14,37,41],"t":1708715280172,"q":6095154,"z":3},{"ev":"T","sym":"PANW","i":"17541","x":11,"p":282.3,"s":1,"c":[37],"t":1708715280172,"q":��%'$8h�-v-<A&
�u2VQP�M!��L�-��b�                                                \6�Vrr�%V�34ĩ'�0��M���6H$�*�E��k4I7/:���
                  0V�5�N�ɟ�W{&6���57#l_[Uʰ�\=N�~0.h*:"UTZ","i":"52992153114486","x":20,"p":19.05,"s":116,"t":1708715280182,"q":1691275,"z":1},{"ev":"T","sym":"SOXS","i":"52983525426519","x":7,"p":4.04,"s":1000,"c":[14,41,60],"t":1708715280178,"q":1139345,"z":1},{"ev":"T","sym":"COIN","i":"11088","x":8,"p":165.02,"s":9,"c":[37],"t":1708715280172,"q":2864946,"z":3},{"ev":"T","sym":"COIN","i":"35144","x":4,"p":165.1,"s":100,"t":1708715280172,"q":2864947,"z":3,"trfi":202,"trft":1708715280172},{"ev":"T","sym":"COIN","i":"4755","x":19,"p":165,"s":25,"c":[14,37,41],"t":1708715280173,"q":2864949,"z":3}]

[ianic]

Made a repo which consistently reproduces panic:

• clone
• build
• start server
• start client

git clone https://github.com/ianic/issue_15226
cd issue_15226
zig build && zig-out/bin/server& ; sleep 1;  zig-out/bin/client ; kill %1

[1] 656675
thread 656677 panic: index out of bounds: index 16658, len 16645
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/crypto/tls/Client.zig:1288:81: 0x109f5ef in finishRead2 (client)
        @memcpy(c.partially_read_buffer[c.partial_ciphertext_idx + first.len ..][0..frag1.len], frag1);
                                                                                ^
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/crypto/tls/Client.zig:1099:35: 0x1099724 in readvAdvanced__anon_4664 (client)
                return finishRead2(c, first, frag1, vp.total);
                                  ^
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/crypto/tls/Client.zig:928:38: 0x10a6f8e in readvAtLeast__anon_4663 (client)
        var amt = try c.readvAdvanced(stream, iovecs[vec_i..]);
                                     ^
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/crypto/tls/Client.zig:889:24: 0x10a7449 in readAtLeast__anon_4661 (client)
    return readvAtLeast(c, stream, &iovecs, len);
                       ^
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/crypto/tls/Client.zig:894:23: 0x10a74e4 in read__anon_4660 (client)
    return readAtLeast(c, stream, buffer, 1);
                      ^
/home/ianic/Code/tmp/issue_15226/src/client.zig:26:31: 0x10ac9f4 in main (client)
        const n = try cli.read(tcp, &buf);
                              ^
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/start.zig:515:37: 0x10971e5 in posixCallMainAndExit (client)
            const result = root.main() catch |err| {
                                    ^
/usr/local/zig/zig-linux-x86_64-0.14.0-dev.208+854e86c56/lib/std/start.zig:258:5: 0x1096d01 in _start (client)
    asm volatile (switch (native_arch) {
    ^
???:?:?: 0x0 in ??? (???)
[2]    656677 IOT instruction (core dumped)  zig-out/bin/client
[1]  + 656675 terminated  zig-out/bin/server