sometimes `max_queued_control_frames` does not send a warning to dmesg

[RomanBelozerov]

TempestaFW - 302ea8c from PR #2108

The max_queued_control_frames directive works correctly and client receive a connection block when it breaks the rule.
But sometimes Warning: Too many control frames in send queue, closing connection warning may not be output to the dmesg

VM does not have limit for net_ratelimit and I didn't see any message suppression

root@tempesta-test-6:~# cat /proc/sys/net/core/message_cost
0

I just receive 1 warning for these tests

Warning: request dropped: incorrect X-Forwarded-For header: 127.0.0.2

but expected

Warning: Too many control frames in send queue, closing connection
Warning: request dropped: incorrect X-Forwarded-For header: 127.0.0.2

Testing

http2_general.test_max_queued_control_frames.TestH2ControlFramesFlood.test_reset_stream_10_limit,
http2_general.test_max_queued_control_frames.TestH2ControlFramesFlood.test_ping,
http2_general.test_max_queued_control_frames.TestH2ControlFramesFlood.test_settings,

there is 1 more test in this directory - http2_general.test_max_queued_control_frames.TestH2ControlFramesFlood.test_reset_stream_default, bit it does not reproduce this problem.
Please change expected number of warning in tests from cond=lambda matches: len(matches) >= 0 to cond=dmesg.amount_one

[kingluo]

@RomanBelozerov @krizhanovsky @const-t
The test case does not set the socket's rcvbuf size, so the default size is big enough to include a bunch of control frame acks. Although asyncore stops reading, the underlying socket will continue reading until the sockbuf is full. Therefore, there is a high probability that the control frame acks are successfully transmitted to the client. It is better not to set such a small number of control frames. That's why the default size of 10000 (http2_general.test_max_queued_control_frames.TestH2ControlFramesFlood.test_reset_stream_default) succeeds always, because it fills up the sockbuf.

The test script tries to fill rcvbuf by requesting a large file, but note that control frame acknowledgments and response chunks are interleaved in the downstream flow, so the control frame acks may be mostly transferred to the client before the response chunk transmission, that is, before sockbuf is full, so the blocking requirement of the test case may become false.

Example:

[Fri May 31 00:50:25 2024] [tempesta fw]       new client socket is accepted: sk=0000000038642ad1, conn=00000000862a4ec7, cli=000000006c6660d1
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=1, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] [tempesta fw]     Matching request: 00000000eb9cca60, list: 0000000093a7703d
[Fri May 31 00:50:25 2024] [tempesta fw]     Matching request: 00000000eb9cca60, list: 00000000aa32c3b1
[Fri May 31 00:50:25 2024] [tempesta fw]     rule: 000000008994914a, field: 0x1, op: 0x1, arg:1:0''
[Fri May 31 00:50:25 2024] [tempesta fw]   frang: check request for client 127.0.0.2, acc=000000009e905f95
[Fri May 31 00:50:25 2024] [tempesta fw]   frang: check incomplete request headers for client 127.0.0.2, acc=000000009e905f95
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x0(Frang_Req_0)
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x1(Frang_Req_Hdr_Method)
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x2(Frang_Req_Hdr_UriLen)
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x3(Frang_Req_Hdr_Check)
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x5(Frang_Req_Body_Start)
[Fri May 31 00:50:25 2024] [tempesta fw]   frang: check incomplete request body for client 127.0.0.2, acc=000000009e905f95
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x6(Frang_Req_Body)
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x8(Frang_Req_Trailer)
[Fri May 31 00:50:25 2024] [tempesta fw]       enter frang FSM at state 0x9(Frang_Req_Done)
[Fri May 31 00:50:25 2024] [tempesta fw]   frang: checks done for client 127.0.0.2
[Fri May 31 00:50:25 2024] [tempesta fw]       Finish frang FSM at state 0x9, ret=0
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x20 len=32540 r=3
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=1, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] [tempesta fw]       connection lost: close client socket: sk=0000000038642ad1, conn=00000000862a4ec7, client=000000006c6660d1
[Fri May 31 00:50:25 2024] [tempesta fw]     put client 000000006c6660d1, users=2
[Fri May 31 00:50:25 2024] [tempesta fw]     put client 000000006c6660d1, users=1
[Fri May 31 00:50:25 2024] [tempesta fw]   put client: cli=000000006c6660d1
[Fri May 31 00:50:25 2024] [tempesta fw]   client was found in tdb
[Fri May 31 00:50:25 2024] [tempesta fw]     client 000000006c6660d1, users=1
[Fri May 31 00:50:25 2024] [tempesta fw]       new client socket: sk=0000000038642ad1, state=1
[Fri May 31 00:50:25 2024] [tempesta fw]   client was found in tdb
[Fri May 31 00:50:25 2024] [tempesta fw]     client 000000006c6660d1, users=2
[Fri May 31 00:50:25 2024] [tempesta fw]       new client socket is accepted: sk=0000000038642ad1, conn=00000000862a4ec7, cli=000000006c6660d1
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=0, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] ---> ctx->queued_control_frames=1, max_queued_control_frames=10
[Fri May 31 00:50:25 2024] [tempesta fw] Warning: request dropped: incorrect X-Forwarded-For header: 127.0.0.2

You can see that just before sockbuf is full, the ping acks are mostly transmitted, so the limit is not triggered.

Check the attachment for package captures for what happens in detail:
test_ping_false_blocking.zip

don't forget to configure the wrieshark the pre-master-secret-log-file: secret.txt.

[kingluo]

@RomanBelozerov @krizhanovsky @const-t
I have to point out another common problem in tempesta-test: when we check the messages in the dmesg log, we don't distinguish the boundaries of test runs, so warning message assertions can be true due to messages from the previous test run, which is why these test cases pass, even though the message didn't actually appear in the current test run. It's better to have an incremental reading of the dmesg log to ensure the correct message assertion.

        self.assertTrue(
            self.oops.find(
                "Warning: Too many control frames in send queue, closing connection",
                cond=lambda matches: len(matches) >= 0,
            ),
            "An unexpected number of dmesg warnings",
        )

[RomanBelozerov]

@kingluo
Yes, you were almost right. max_queued_control_frames works correctly. The problem was in the tests.

The main problem in these tests - deproxy thread does not have time to open connection and the main thread calls the wait_for_connection_close and restart for client. As a result, we do not receive a warning in dmesg. I fixed tests here.

Also we have the problem with warning. You should add \n to this warning to output the message to dmesg without delay.

I close issue because the problem was in tests and I fixed it.

[kingluo]

Sorry, I'm afraid this doesn't solve the problem.

As I mentioned above, response chunks for large responses are interleaved with control frame ACKs, so you cannot guarantee that enough chunks will be delivered before the control frame ACK to fill the deproxy client's sockbuf and ensure that the latter will block due to the TCP window becoming 0.

client.readable = lambda: True only prevents asyncore from processing epoll read events, but does not prevent the linux kernel from reading data from the TCP socket. Control frame flooding is a slow read attack that relies on TCP-level read blocking.

Please look at my example above (the tcpdump file and log file) for a visual example of my clarification.

So, the correct approach is to use setsockopt() to set a sockbuf small enough so that it is not large enough to hold all the control frame acknowledgments.

[RomanBelozerov]

Ok. I saw the tcpdump file and log file. But they is not correct because as I mentioned above, the tests did not work correctly. Please add \n to warning in TempstaFW and check new version of the tests.

[RomanBelozerov]

I reworked the tests using socket.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, 1024), but it does not work without filling the buffer. So I use this way:

1. set a small buffer for client; (it is needed for stability of tests. The different VMs have a different size of buffer);
2. request a large data from backend and disable socket for reading. Tempesta can not send any data to the client until the client enable socket for reading;
3. wait until the client buffer is full; (this is needed to avoid interleaving of data frames and ping ACKs);
4. send number of attack frames (limit +10% for stability of test);
5. wait for connection close and warning from dmesg;

In this case we check that max_queued_control_frames limit works correctly. But we are not simulated attack