Fix 'Client output buffer hard limit is enforced' test causing infinite loop on macOS 15.4

[vitahlin]

This PR fixes an issue in the CI test for client-output-buffer-limit, which was causing an infinite loop when running on macOS 15.4.

Problem

This test start two clients, R and R1:

R1 subscribe foo
R publish foo bar

When R executes PUBLISH foo bar, the server first stores the message bar in R1‘s buf. Only when the space in buf is insufficient does it call _addReplyProtoToList.
Inside this function, closeClientOnOutputBufferLimitReached is invoked to check whether the client’s R1 output buffer has reached its configured limit.
On macOS 15.4, because the server writes to the client at a high speed, R1’s buf never gets full. As a result, closeClientOnOutputBufferLimitReached in the test is never triggered, causing the test to never exit and fall into an infinite loop.

I modify the test like this, print client information and the number of loop iterations:

test {Client output buffer hard limit is enforced} {
    r config set client-output-buffer-limit {pubsub 100000 0 0}
    set rd1 [valkey_deferring_client]

    $rd1 subscribe foo
    set reply [$rd1 read]
    assert {$reply eq "subscribe foo 1"}

    set omem 0
    set loopTime 0
    while 1 {
        incr loopTime
        puts "---currentLoop: $loopTime---"
        r publish foo bar
        set clients [split [r client list] "\r\n"]
        set c [split [lindex $clients 1] " "]
        puts "clients: $clients"
        if {![ regexp {omem=([0-9]+)} $c - omem]} break
        if {$omem > 200000} break
    }
    assert {$omem >= 70000 && $omem < 200000}
    $rd1 close
}

The run test ./runtest --single "unit/obuf-limits" --only "Client output buffer hard limit is enforced"

Run on ubuntu

---currentLoop: 1792---
clients: {id=3 addr=127.0.0.1:34783 laddr=127.0.0.1:21611 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=701 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=2797417 tot-net-out=1248318 tot-cmds=3585} {id=4 addr=127.0.0.1:45357 laddr=127.0.0.1:21611 fd=11 name= age=0 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=1536 rbp=1536 obl=1536 oll=4 omem=82016 tot-mem=84120 events=rw cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=2670937 tot-cmds=2} {}
---currentLoop: 1793---
clients: {id=3 addr=127.0.0.1:34783 laddr=127.0.0.1:21611 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=701 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=2798978 tot-net-out=1249023 tot-cmds=3587} {id=4 addr=127.0.0.1:45357 laddr=127.0.0.1:21611 fd=11 name= age=0 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=1536 rbp=1536 obl=1536 oll=4 omem=82016 tot-mem=84120 events=rw cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=2670937 tot-cmds=2} {}
---currentLoop: 1794---
clients: {id=3 addr=127.0.0.1:34783 laddr=127.0.0.1:21611 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=701 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=2800539 tot-net-out=1249728 tot-cmds=3589} {id=4 addr=127.0.0.1:45357 laddr=127.0.0.1:21611 fd=11 name= age=0 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=1536 rbp=1536 obl=1536 oll=4 omem=82016 tot-mem=84120 events=rw cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=2670937 tot-cmds=2} {}
---currentLoop: 1795---
clients: {id=3 addr=127.0.0.1:34783 laddr=127.0.0.1:21611 fd=10 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=701 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=2802100 tot-net-out=1250433 tot-cmds=3591} {}
[ok]: Client output buffer hard limit is enforced (360 ms)

Run on macOS

---currentLoop: 302377---
clients: {id=3 addr=127.0.0.1:53771 laddr=127.0.0.1:21111 fd=12 name= age=36 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=698 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=18445102 tot-net-out=211406394 tot-cmds=604755} {id=4 addr=127.0.0.1:53772 laddr=127.0.0.1:21111 fd=13 name= age=36 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=1024 rbp=35 obl=0 oll=0 omem=0 tot-mem=1592 events=r cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=10583232 tot-cmds=2} {}
---currentLoop: 302378---
clients: {id=3 addr=127.0.0.1:53771 laddr=127.0.0.1:21111 fd=12 name= age=36 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=698 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=18445163 tot-net-out=211407096 tot-cmds=604757} {id=4 addr=127.0.0.1:53772 laddr=127.0.0.1:21111 fd=13 name= age=36 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=1024 rbp=35 obl=0 oll=0 omem=0 tot-mem=1592 events=r cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=10583267 tot-cmds=2} {}
---currentLoop: 302379---
clients: {id=3 addr=127.0.0.1:53771 laddr=127.0.0.1:21111 fd=12 name= age=36 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=698 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=18445224 tot-net-out=211407798 tot-cmds=604759} {id=4 addr=127.0.0.1:53772 laddr=127.0.0.1:21111 fd=13 name= age=36 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=1024 rbp=35 obl=0 oll=0 omem=0 tot-mem=1592 events=r cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=10583302 tot-cmds=2} {}
---currentLoop: 302380---

The omem is always 0 and the loop never ends.

Fixed

I changed r publish foo bar to r publish foo [string repeat bar 50] to ensure the buffer is filled, which correctly reproduces the scenario where omem increases.

New test with printf content:

test {Client output buffer hard limit is enforced} {
    r config set client-output-buffer-limit {pubsub 100000 0 0}
    set rd1 [redis_deferring_client]

    $rd1 subscribe foo
    set reply [$rd1 read]
    assert {$reply eq "subscribe foo 1"}

    set omem 0
    set loopTime 0
    while 1 {
        incr loopTime
        puts "---currentLoop: $loopTime---"
        r publish foo [string repeat bar 50]
        set clients [split [r client list] "\r\n"]
        set c [split [lindex $clients 1] " "]
        puts "clients: $clients"
        if {![ regexp {omem=([0-9]+)} $c - omem]} break
        if {$omem > 200000} break
    }
    assert {$omem >= 70000 && $omem < 200000}
    $rd1 close
}

Test result:

---currentLoop: 3496---
clients: {id=3 addr=127.0.0.1:54002 laddr=127.0.0.1:21611 fd=12 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=699 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=734265 tot-net-out=2430899 tot-cmds=6993} {id=4 addr=127.0.0.1:54003 laddr=127.0.0.1:21611 fd=13 name= age=0 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=2048 rbp=1024 obl=1024 oll=5 omem=84600 tot-mem=87216 events=rw cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=558109 tot-cmds=2} {}
---currentLoop: 3497---
clients: {id=3 addr=127.0.0.1:54002 laddr=127.0.0.1:21611 fd=12 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=699 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=734475 tot-net-out=2431602 tot-cmds=6995} {id=4 addr=127.0.0.1:54003 laddr=127.0.0.1:21611 fd=13 name= age=0 idle=0 flags=P capa= db=9 sub=1 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=0 multi-mem=0 rbs=2048 rbp=1024 obl=1024 oll=5 omem=84600 tot-mem=87216 events=rw cmd=subscribe user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=51 tot-net-out=558109 tot-cmds=2} {}
---currentLoop: 3498---
clients: {id=3 addr=127.0.0.1:54002 laddr=127.0.0.1:21611 fd=12 name= age=0 idle=0 flags=N capa= db=9 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=0 argv-mem=10 multi-mem=0 rbs=1024 rbp=699 obl=0 oll=0 omem=0 tot-mem=1562 events=r cmd=client|list user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=734685 tot-net-out=2432305 tot-cmds=6997} {}
[ok]: Client output buffer hard limit is enforced (427 ms)

[rjd15372]

LGTM

@zuiderkwast care to take a look?

[zuiderkwast]

This is no guarantee, but if makes the test less flaky, I'm going to merge it. Thanks!

I wonder if there is a way to actually make sure the data stays in the output buffer...

[vitahlin]

This is no guarantee, but if makes the test less flaky, I'm going to merge it. Thanks!

I wonder if there is a way to actually make sure the data stays in the output buffer...

You’re right — I reviewed the macOS 15.4 release notes and found no mention of any changes or optimizations related to socket buffer sizes. I’m still investigating why publish foo a does not appear to trigger the output buffer limit on macOS 15.4, and I’ll share any findings as I go.

[vitahlin]

This issue exists with both Redis and Valkey, and the following test content is also applicable to Valkey.

@zuiderkwast
I modified the test to print the number of loop iterations and used netstat to check the socket’s Send-Q and Recv-Q values.

test {Client output buffer hard limit is enforced} {
        r config set client-output-buffer-limit {pubsub 100000 0 0}
        set rd1 [redis_deferring_client]

        $rd1 subscribe foo
        set reply [$rd1 read]
        assert {$reply eq "subscribe foo 1"}

        set omem 0
        set loop_count 0
        while 1 {
            incr loop_count
            if { [expr {$loop_count % 10}] == 0 } {
                puts ""
                puts "---loop_times $loop_count---"
            }
            r publish foo [string repeat a 1]
            set clients [split [r client list] "\r\n"]
            set c [split [lindex $clients 1] " "]
            if { [expr {$loop_count % 10}] == 0 } {
                puts "clients: $clients"
                set netstat_output [exec sh -c {
                    netstat -anv | grep "$(lsof -iTCP -sTCP:ESTABLISHED -nP | grep redis | sed -n '2p' | awk -F'[:> ]' '{print $(NF-1)}')"
                }]
                puts $netstat_output
            }
            if {![regexp {omem=([0-9]+)} $c - omem]} break
            if {$omem > 200000} break
        }
        assert {$omem >= 70000 && $omem < 200000}

        $rd1 close
    }

Test publish foo a on macOS 15.3.2

The result like this:

Based on the results, the server’s send-q increases as expected.

Test publish foo a on macOS 15.4

The server’s send-q increases as expected, but sometimes it gets processed and cleared.

After the loop runs for a while, the server’s send-q stays almost constantly at 0, while the client’s recv-q keeps increasing normally.
The data sent from the server to the client is always being processed, so omem doesn’t increase either.

Test publish foo aaaaa.... on macOS 15.4

Modify the publish command like this:

r publish foo [string repeat a 100]

The server’s send-q increases as expected.

I couldn’t find any relevant documentation on macOS 15.4, but I believe these test results are sufficient to suggest that macOS 15.4 has introduced some special optimizations. We need to increase the amount of data being written to ensure that the socket’s Send-Q isn’t fully drained — only then will omem increase as expected.