`std.http.Client` hangs indefinitely on response body sizes > 4096 bytes

[ultd]

Zig Version

0.11.0-dev.3107+6547d2331

Steps to Reproduce and Observed Behavior

Make a https request using the std.http.Client and set transfer_encoding to .chunked on the request like so:

        var client: http.Client = .{ .allocator = allocator };
        var req = try client.request(http.Method.POST, http_endpoint, default_http_headers, .{});
        req.transfer_encoding = .chunked;
        defer req.deinit();

        try req.start();
        try req.writer().writeAll(reqBody);  // reqBody is just []u8
        try req.finish();
        try req.wait();

        if (req.response.status != http.Status.ok) {
            return Error.ResponseNotStatusOk;
        }

        const respBody = try req.reader().readAllAlloc(self.allocator, 12 * 1024 * 1024); // 12Mb max size set
        defer self.allocator.free(body);

        // do something with respBody

Once you surpass a certain body size (greater than 4096 i believe), it will remain stuck in an infinite loop. The response body size of the request which causes this issue is much smaller than 12Mb - it's around 3.4Mb. If I make request under 4Kb it seems to work fine.

I tracked the bug to BufferedConnection.readAtLeast and it seems it's stuck in the while (out_index < len) loop.

I logged values of the vars that affect this loop like so:

pub fn readAtLeast(bconn: *BufferedConnection, buffer: []u8, len: usize) ReadError!usize {
        var out_index: u16 = 0;
        while (out_index < len) {
            std.log.debug("readAtLeast.while - begin", .{});
            const available = bconn.read_end - bconn.read_start;
            const left = buffer.len - out_index;

            if (available > 0) {
                const can_read = @intCast(u16, @min(available, left));
                std.log.debug("readAtLeast.while - available: {}, left: {}, can_read: {}", .{ available, left, can_read });

                @memcpy(buffer[out_index..][0..can_read], bconn.read_buf[bconn.read_start..][0..can_read]);
                out_index += can_read;
                bconn.read_start += can_read;

                continue;
            }
            std.log.debug("readAtLeast.while - passed continue", .{});

            if (left > bconn.read_buf.len) {
                // skip the buffer if the output is large enough
                return bconn.conn.read(buffer[out_index..]);
            }

            try bconn.fill();
            std.log.debug("readAtLeast.while - end", .{});
        }
        std.log.debug("readAtLeast - returning", .{});

        return out_index;
    }

and it produces these logs continuously:

...
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
debug: readAtLeast.while - begin
debug: readAtLeast.while - available: 12536, left: 0, can_read: 0
...

Also, sometimes it doesn't get stuck in loop and returns this error instead (~20% of the time):

thread 1290939 panic: @memcpy arguments have non-equal lengths
/Users/bkk/bin/zig/lib/std/crypto/tls/Client.zig:1062:25: 0x104c0671b in readvAdvanced__anon_13130 (main)
            @memcpy(frag[0..in], first);
                        ^
/Users/bkk/bin/zig/lib/std/crypto/tls/Client.zig:898:53: 0x104c046cf in readvAtLeast__anon_13129 (main)
        var amt = try c.readvAdvanced(stream, iovecs[vec_i..]);
                                                    ^
/Users/bkk/bin/zig/lib/std/crypto/tls/Client.zig:859:24: 0x104c044b3 in readAtLeast__anon_13127 (main)
    return readvAtLeast(c, stream, &iovecs, len);
                       ^
/Users/bkk/bin/zig/lib/std/crypto/tls/Client.zig:864:23: 0x104c043d3 in read__anon_13126 (main)
    return readAtLeast(c, stream, buffer, 1);
                      ^
/Users/bkk/bin/zig/lib/std/http/Client.zig:173:46: 0x104bc9e77 in read (main)
            .tls => conn.tls_client.read(conn.stream, buffer),
                                             ^
/Users/bkk/bin/zig/lib/std/http/Client.zig:267:57: 0x104b7966b in fill (main)
        const nread = try bconn.conn.read(bconn.read_buf[0..]);
                                                        ^
/Users/bkk/bin/zig/lib/std/http/protocol.zig:553:35: 0x104b78f9f in read__anon_7953 (main)
                    try bconn.fill();
                                  ^
/Users/bkk/bin/zig/lib/std/http/Client.zig:686:111: 0x104b7a87b in transferRead (main)
            const amt = try req.response.parser.read(&req.connection.data.buffered, buf[index..], req.response.skip);
                                                                                                              ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:27:31: 0x104bdee07 in read (main)
            return readFn(self.context, buffer);
                              ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:243:50: 0x104d1240b in readByte (main)
            const amt_read = try self.read(result[0..]);
                                                 ^
/Users/bkk/bin/zig/lib/std/compress/deflate/decompressor.zig:822:47: 0x104bdb8d7 in moreBits (main)
            var c = self.inner_reader.readByte() catch |e| {
                                              ^
/Users/bkk/bin/zig/lib/std/compress/deflate/decompressor.zig:412:30: 0x104b8443f in nextBlock (main)
                self.moreBits() catch |e| {
                             ^
/Users/bkk/bin/zig/lib/std/compress/deflate/decompressor.zig:471:26: 0x104be05db in read (main)
                self.step(self) catch |e| {
                         ^
/Users/bkk/bin/zig/lib/std/compress/gzip.zig:128:45: 0x104b88573 in read (main)
            const r = try self.inflater.read(buffer);
                                            ^
/Users/bkk/bin/zig/lib/std/http/Client.zig:814:39: 0x104b87c17 in read (main)
            .gzip => |*gzip| gzip.read(buffer) catch return error.DecompressionFailure,
                                      ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:27:31: 0x104be46b3 in read (main)
            return readFn(self.context, buffer);
                              ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:46:49: 0x104b8929f in readAtLeast (main)
                const amt = try self.read(buffer[index..]);
                                                ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:34:52: 0x104b69727 in readAll (main)
            return readAtLeast(self, buffer, buffer.len);
                                                   ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:80:52: 0x104b6913b in readAllArrayListAligned__anon_6214 (main)
                const bytes_read = try self.readAll(dest_slice);
                                                   ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:65:48: 0x104b68f03 in readAllArrayList (main)
            return self.readAllArrayListAligned(null, array_list, max_append_size);
                                               ^
/Users/bkk/bin/zig/lib/std/io/reader.zig:105:38: 0x104b698e3 in readAllAlloc (main)
            try self.readAllArrayList(&array_list, max_size);

Expected Behavior

It should not hang indefinitely.

[ultd]

I have a hunch #15704 fixes this but not entirely sure, seems related.

[ryansname]

@ultd I'm running into this messing with the new package manager stuff, trying to download an archive from git. Using a version of #15704, I'm seeing the second problem you mentioned: thread 1290939 panic: @memcpy arguments have non-equal lengths every time without fail some of the time.

[kamidev]

I am also getting thread 1290939 panic: @memcpy arguments have non-equal lengths . This happens every time I try to build https://github.com/zigzap/zap, which uses the new package manager. I am on zig master, currently 0.11.0-dev.3177+e584dd806.

[renerocksai]

I suspect #15590 is related

[truemedian]

The infinite loop looks to be an issue related to potentially attempting to read into a zero-length buffer. I'll look into this and see what I can find and fix.

[dec05eba]

The infinite loop looks to be an issue related to potentially attempting to read into a zero-length buffer. I'll look into this and see what I can find and fix.

This appears to be the issue when I looked at it too. I managed to fix the hanging and get the whole body response by adding

if (out_avail == 0) {
    return out_index;
}

after lib/std/http/protocol.zig:576. But I dont think that this is the correct solution. r.next_chunk_length appears to be 1 while out_avail is 0. Something similar probably also needs to be done in the other switch cases.
Tested on GET to https://google.com

[dec05eba]

#15927 didn't appear to fix this, at least when used with https://google.com. It now hits an assert that was added to readAtLeast. Here is an example code to reproduce it:

const std = @import("std");
const uri = std.Uri.parse("https://google.com") catch unreachable;

pub fn main() !void {
    var arena = std.heap.ArenaAllocator.init(std.heap.page_allocator);
    defer arena.deinit();
    var allocator = arena.allocator();

    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 body = try req.reader().readAllAlloc(allocator, 2<<24);
    defer allocator.free(body);
}

and here is the error stack trace:

thread 5803 panic: reached unreachable code
/home/dec05eba/zig/lib/std/debug.zig:260:14: 0x32927c in assert (main)
    if (!ok) unreachable; // assertion failure
             ^
/home/dec05eba/zig/lib/std/http/Client.zig:202:15: 0x43fb0e in readAtLeast (main)
        assert(len <= buffer.len);
              ^
/home/dec05eba/zig/lib/std/http/Client.zig:238:32: 0x3696fa in read (main)
        return conn.readAtLeast(buffer, 1);
                               ^
/home/dec05eba/zig/lib/std/http/protocol.zig:586:52: 0x369250 in read__anon_8827 (main)
                        const nread = try conn.read(buffer[out_index..][0..can_read]);
                                                   ^
/home/dec05eba/zig/lib/std/http/Client.zig:628:53: 0x338c7f in transferRead (main)
            const amt = try req.response.parser.read(&req.connection.data, buf[index..], req.response.skip);
                                                    ^
/home/dec05eba/zig/lib/std/io/reader.zig:27:26: 0x48443b in read (main)
            return readFn(self.context, buffer);
                         ^
/home/dec05eba/zig/lib/std/io/reader.zig:242:43: 0x442d8a in readByte (main)
            const amt_read = try self.read(result[0..]);
                                          ^
/home/dec05eba/zig/lib/std/compress/deflate/decompressor.zig:822:47: 0x36ce41 in moreBits (main)
            var c = self.inner_reader.readByte() catch |e| {
                                              ^
/home/dec05eba/zig/lib/std/compress/deflate/decompressor.zig:706:54: 0x36e1b2 in huffmanBlock (main)
                                    try self.moreBits();
                                                     ^
/home/dec05eba/zig/lib/std/compress/deflate/decompressor.zig:437:42: 0x335f90 in nextBlock (main)
                    try self.huffmanBlock();
                                         ^
/home/dec05eba/zig/lib/std/compress/deflate/decompressor.zig:471:26: 0x4cefe7 in read (main)
                self.step(self) catch |e| {
                         ^
/home/dec05eba/zig/lib/std/compress/gzip.zig:128:45: 0x485262 in read (main)
            const r = try self.inflater.read(buffer);
                                            ^
/home/dec05eba/zig/lib/std/http/Client.zig:756:39: 0x44537e in read (main)
            .gzip => |*gzip| gzip.read(buffer) catch return error.DecompressionFailure,
                                      ^
/home/dec05eba/zig/lib/std/io/reader.zig:27:26: 0x3700cb in read (main)
            return readFn(self.context, buffer);
                         ^
/home/dec05eba/zig/lib/std/io/reader.zig:46:42: 0x33a1f2 in readAtLeast (main)
                const amt = try self.read(buffer[index..]);
                                         ^
/home/dec05eba/zig/lib/std/io/reader.zig:34:31: 0x323aa0 in readAll (main)
            return readAtLeast(self, buffer, buffer.len);
                              ^
/home/dec05eba/zig/lib/std/io/reader.zig:80:52: 0x3235f5 in readAllArrayListAligned__anon_6100 (main)
                const bytes_read = try self.readAll(dest_slice);
                                                   ^
/home/dec05eba/zig/lib/std/io/reader.zig:65:48: 0x323413 in readAllArrayList (main)
            return self.readAllArrayListAligned(null, array_list, max_append_size);
                                               ^
/home/dec05eba/zig/lib/std/io/reader.zig:105:38: 0x323c05 in readAllAlloc (main)
            try self.readAllArrayList(&array_list, max_size);
                                     ^
/home/dec05eba/git/qm-rumble/src/main.zig:17:47: 0x3244c2 in main (main)
    const body = try req.reader().readAllAlloc(allocator, 2<<24);
                                              ^
/home/dec05eba/zig/lib/std/start.zig:609:37: 0x3230fe in posixCallMainAndExit (main)
            const result = root.main() catch |err| {
                                    ^
/home/dec05eba/zig/lib/std/start.zig:368:5: 0x322b61 in _start (main)
    @call(.never_inline, posixCallMainAndExit, .{});

tested with zig version 0.11.0-dev.3380+7e0a02ee2 (latest master at the moment)

[dec05eba]

Ok, it "works" when compiling in ReleaseFast mode (as that assert is disabled and it's not stuck in an infinite loop). But that means that readAtLeast is not reading at least "len" bytes as it describes, I guess?. There seems to be a conflict between that assert and

zig/lib/std/http/Server.zig

Line 68 in 7e0a02e

if (available_read > available_buffer) { // partially read buffered data

comment and the break inside that points to being able to read partial data instead of reading len bytes.

[truemedian]

That assert being triggered means that something is requesting more bytes than they have space to store, which is impossible. The comment on that line refers to partially reading the buffer (ie. not completely consuming it, which means the output buffer will be completely full).

The only other place that I can see this coming from is in protocol.zig:

/home/dec05eba/zig/lib/std/http/protocol.zig:586:52: 0x369250 in read__anon_8827 (main)
                        const nread = try conn.read(buffer[out_index..][0..can_read]);

My guess is that can_read here is probably zero, which means that it shouldn't be even attempting to read.