http: Log bytes received from client, use to replace receive-throttle regression test #36303

pinheadmz commented at 4:18 PM on September 20, 2026: member

Improves and fixes the test introduced by #36123 to cover regressions in the server's receive throttle. The original test relied on client-side signals to assert server-side behavior which can easily be disrupted by a platform's TCP stack. Macos for example may suddenly re-open a TCP window size based on heuristics out of our control (SB_AUTOSIZE), despite the application not reading any data from the socket. Macos also may delay transmission of data between 5-60 seconds as the TCP window shrinks (TCPTV_PERSMIN / TCPT_PERSIST / "silly window syndrome" avoidance). All these behaviors were observed by running the current CI test on my fork hundreds of times, capturing TCP packets and processing them locally against the CI debug log.

The improved approach is similar to how we test the send-side throttle in #36174 using debug log messages. This way we test the thing we know we can control (bitcoind).

To introduce the regression patched by #36123 and fail the new test:

diff --git a/src/httpserver.cpp b/src/httpserver.cpp
--- a/src/httpserver.cpp
+++ b/src/httpserver.cpp
@@ -1040,13 +1040,7 @@ HTTPServer::IOReadiness HTTPServer::GenerateWaitSockets() const
         // before the next is taken and they stay separate critical sections.
         // Holding m_sock_mutex while acquiring m_send_mutex would invert that
         // order and risk a lock-order-inversion deadlock.
-        Sock::Event event{0};
-        if (http_client->ReadyToSend()) {
-            event = Sock::SendEvent;
-        } else if (http_client->GetRequest() != nullptr || http_client->ReceiveBufferEmpty()) {
-            // Mid-parse (need more bytes) or buffer empty.
-            event = Sock::RecvEvent;
-        }
+        Sock::Event event = (http_client->ReadyToSend() ? Sock::SendEvent : Sock::RecvEvent);
 
         io_readiness.events_per_sock.emplace(sock, Sock::Events{event});
         io_readiness.httpclients_per_sock.emplace(sock, http_client);

For usual bitcoind activity, httpo debug logs will only grow by one extra line per request. Huge requests like those generated by the test may produce a hundred or so lines of "Received data" messages. These are optional debug lines in a worst-case scenario, but reviewers can discuss rate-limiting that log activity if we're afraid it's too much.

http: log received bytes per client read 767d86aaa7

DrahtBot added the label RPC/REST/ZMQ on Sep 20, 2026

DrahtBot commented at 4:18 PM on September 20, 2026: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

External sites

Code coverage & benchmarks: https://corecheck.dev/bitcoin/bitcoin/pulls/36303
Ralph review <img src=https://review.fish.foo/assets/bitcoin/bitcoin/36303.png alt="Ralph review status"> https://git.fish.foo/bitcoin/bitcoin/pulls/36303#author-ralph

Reviews

See the guideline and AI policy for information on the review process.

Type	Reviewers
ACK	winterrdog, davidgumberg, ismaelsadeeq, achow101
Stale ACK	151henry151

If your review is incorrectly listed, please copy-paste <code></code> into the comment that the bot should ignore.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#36434 <sub><img src="https://drahtbot.space/ack_count/bitcoin/bitcoin/36434.svg"></sub> (http: support unix sockets by pinheadmz)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

LLM Linter (✨ experimental)

Possible typos and grammar issues:

macos -> macOS [misspelled proper name]

151henry151 commented at 9:57 PM on September 20, 2026: contributor

Tested ACK f86eb92d9a

tip: interface_http.py passes with the PR unthrottle diff: fails (flood thread assert)

<!--

in test/functional/interface_http.py:807 in f86eb92d9a

 839 | +            while True:
 840 | +                # Check the background thread for assertion errors
 841 | +                if flood_thread.done():
 842 | +                    flood_thread.result()
 843 | +
 844 | +                # Read only the new log bytes written since the last poll.

hodlinator commented at 1:32 PM on September 21, 2026:

This doesn't seem to be true unless we rename dl_start_size to dl_prev_size and update the value?

pinheadmz commented at 1:46 PM on September 21, 2026:

hm, must have lost that in a rebase before pushing. thanks for catching, will fix.

pinheadmz commented at 2:00 PM on September 21, 2026:

Sorry, I think existing code is correct actually: while True { dl.read() } will always start from where it left off in the previous loop (i.e. only read any new lines added to file since last loop).

I didn't have this in the next test though from #36174 though, but could add it here.

hodlinator commented at 3:04 PM on September 21, 2026:

Ah yes, I see now that dl.seek(dl_start_size) is outside the while-loop in this test, unlike the one from #36174. assert_debug_log both re-opens and re-seeks... to prev_size which is not updated as I was expecting. I guess that serves a paranoid guard against half-completed lines in the assert_debug_log case.

in test/functional/interface_http.py:822 in f86eb92d9a

 863 | +                tries -= 1
 864 | +                assert tries > 0, (
 865 | +                    f"Server kept reading pipelined data ({total} bytes received, "
 866 | +                    f"{buffered} buffered) while a request was still in flight.")
 867 | +                self.log.debug(f"Server read {total} bytes, {buffered} buffered")
 868 | +                time.sleep(5)

davidgumberg commented at 9:42 PM on September 22, 2026:

Should this be time.sleep(0.05)?

Currently the test would take 5 minutes to time out

davidgumberg commented at 10:18 PM on September 22, 2026:

But I guess the way the test is currently set up, because it succeeds after the first time it sees a stall, you have to give the flood some time, maybe instead the number of tries should be greatly reduced?

pinheadmz commented at 1:48 PM on September 23, 2026:

Yeah it's intentionally a 5 minute timeout (explicit in the comment above) but if you test the regression locally you'll probably find that the test exits much earlier based on the amount of data consumed by the socket:

assert sent_total < len(flood) * 10, f"Client sent too much data: {sent_total}"

Both of these boundaries (data sent, time) were chosen at somewhat excessive values to avoid false negatives like the original test.

davidgumberg commented at 7:28 PM on September 23, 2026:

(speculative; non-blocking)

Both failure limits seem so big, and the test is so eager to pass on the first sign of stalling that this test seems like it could miss actual issues is my hunch, but I don't know what other values to suggest.

in test/functional/interface_http.py:813 in f86eb92d9a outdated

 845 | +                log = dl.read()
 846 | +                matches = re.findall(
 847 | +                    rf"Received (\d+) bytes from [^\s]*:{local_port} \(id=\d+\): total=(\d+) buffered=(\d+)",
 848 | +                    log)
 849 | +                total = max((int(m[1]) for m in matches), default=total)
 850 | +                buffered = max((int(m[2]) for m in matches), default=buffered)

davidgumberg commented at 11:03 PM on September 22, 2026:

style nanonit, feel free to disregard and only if retouching:

~wrong, see below~

</summary>

                matches = re.finditer(
                    rf"Received (?P<received>\d+) bytes from [^\s]*:{local_port} "
                    rf"\(id=\d+\): total=(?P<total>\d+) buffered=(?P<buffered>\d+)",
                    log,
                )
                total = max((int(m.group("total")) for m in matches), default=total)
                buffered = max((int(m.group("buffered")) for m in matches), default=buffered)

pinheadmz commented at 8:04 PM on September 24, 2026:

A little bot told me that since finditer returns a single-use iterator, matches will already be used up by the time you get to buffered = ... so it'll stay at 0 no matter what.

Observable in the log if you set the flood to never stop (assert sent_total < len(flood) * 1000000000):

TestFramework (DEBUG): Server read 6847787579 bytes, 0 buffered

davidgumberg commented at 8:28 PM on September 24, 2026:

oops sorry, I only meant to change the pattern:

                matches = re.findall(
                    rf"Received \d+ bytes from [^\s]*:{local_port} "
                    rf"\(id=\d+\): total=(?P<total>\d+) buffered=(?P<buffered>\d+)",
                    log,
                )
                total = max((int(m.group("total")) for m in matches), default=total)
                buffered = max((int(m.group("buffered")) for m in matches), default=buffered)

also should probably drop the unused capture group if you prefer the unnamed capture group approach but that's also not blocking for me:

                matches = re.findall(
                    rf"Received \d+ bytes from [^\s]*:{local_port} \(id=\d+\): total=(\d+) buffered=(\d+)",
                    log)
                total = max((int(m[0]) for m in matches), default=total)
                buffered = max((int(m[1]) for m in matches), default=buffered)

davidgumberg commented at 11:27 PM on September 25, 2026:

@pinheadmz if leaving as-is can you drop the first match group since it's unused?

davidgumberg commented at 11:28 PM on September 25, 2026:

or say no and mark this resolved, also fine

pinheadmz commented at 11:33 PM on September 25, 2026:

yeah sorry, cleaning up...

sedited added the label Needs Backport (32.x) on Sep 23, 2026

davidgumberg commented at 9:39 PM on September 23, 2026: contributor

crACK f86eb92d9a5b2ef349c7002fb3bcb44f371870e0

It seems a bit odd to me that the throttle doesn't clamp on once there's a request being processed by the application, but only after that happens and a second message is sent, I think it would be good to also do something like #36276 mainly for code correctness reasons (with a fix for the 50ms select timeout that branch had), but I also recognize that the severity of this DoS vector is extremely low, and this testing approach is much better than the old one which seems inherently flaky for the reasons in PR description, and a good enough fix.

I also think 5 minutes to time out in the failure case is far too generous, intermittent failures are bad but so are tests that are too eager to not fail, and I can't see a good justification for why the http server would continue reading from the socket 60 times after the clamp should have started. IIUC the existing test failure that is observed is because of the ~bug-ish that we'll read one more message after we should have put the clamp on, and I don't see how it could plausibly happen more than once [maybe twice if unlucky] that more data is read, but maybe I have misunderstood something.

maflcko added this to the milestone 32.0 on Sep 24, 2026

pinheadmz commented at 7:44 PM on September 24, 2026: member

IIUC the existing test failure that is observed is because of the ~bug-ish that we'll read one more message after we should have put the clamp on

The test failure was due to a chain of black-box socket behaviors between the server and client. Without log messages the only way to detect the server throttle was with socket errors on the client side. Problem is there's too many things that can cause those socket errors and even worse, sometimes they go away and data transmission continues. That's all due to behavior in the macos kernel.

I confess I was misled by LLM review that the "bug" was causing the test failures and it was your comment on that PR that really made me step through everything again with my meatball brain and I couldn't answer the fundamental question "how does this patch in the server fix the test?"

I used packet capture to try and nail down the issue and eventually came to the conclusion that there wasn't one issue but many, and all out of control of bitcoind.

And then yeah, its hard to pick constants for how long it should take for something not to happen. If the server code is broken and a ci machine is so slow it takes 6 seconds to read data from a socket then we'll have a false positive. I'd be happy bumping that to 10 or 5 * TIMEOUT_FACTOR or something? It just means safe/patched servers will sit in the test for that long before passing.

On the other end (5 minutes) I observed some CI runs that false-failed because the TCP was so slow it took a minute for the throttle to kick in at all. Again, could be a role for TIMEOUT_FACTOR.

Could borrow the approach @maflcko wrote in #36324

in test/functional/interface_http.py:776 in f86eb92d9a outdated

 808 | +            while flood_open:
 809 | +                try:
 810 | +                    sent = conn.conn.sock.send(flood)
 811 | +                    sent_total += sent
 812 | +                    blocked = False
 813 | +                    self.log.debug(f"Client sent {sent} (total {sent_total})")

winterrdog commented at 8:05 PM on September 24, 2026:

nit: i think we can rip out the ambiguity like so:

                    self.log.debug(f"Client sent {sent} bytes (total {sent_total} bytes)")

pinheadmz commented at 11:26 AM on September 25, 2026:

👍

in test/functional/interface_http.py:780 in f86eb92d9a outdated

 812 | +                    blocked = False
 813 | +                    self.log.debug(f"Client sent {sent} (total {sent_total})")
 814 | +                except BlockingIOError:
 815 | +                    if not blocked:
 816 | +                        blocked = True
 817 | +                        self.log.debug(f"Client socket blocked after sending {sent_total}")

winterrdog commented at 8:07 PM on September 24, 2026:

nit: same here. i think we can rip out the ambiguity:

                        self.log.debug(f"Client socket blocked after sending {sent_total} bytes")

pinheadmz force-pushed on Sep 24, 2026

pinheadmz commented at 8:27 PM on September 24, 2026: member

push to b481e99e3018ce218570b4d8173b729c548a5ce3

Apply timeout_factor to the progress check, like #36324

in test/functional/interface_http.py:766 in f86eb92d9a

 798 | +        # thread has determined that the server is throttling correctly.
 799 | +        # We can't rely on TCP backpressure at the client socket to assert
 800 | +        # server behavior because different platforms (macos in particular)
 801 | +        # like to open and close the TCP window size based on heuristics
 802 | +        # out of our control, and delay transmission when windows get too small.
 803 | +        flood_open = True

winterrdog commented at 8:43 PM on September 24, 2026:

non-blocking suggestion: do you think threading.Event() would be a better option since it is an explicit synchronisation primitive instead of relying on the python's GIL implicitly ?

it could also replace the time.sleep(0.05) in send_flood with sth like flood_open.wait(0.05) which can stop blocking early the instant .set() is called elsewhere, so teardown becomes up to 50ms snappier and in the end not always paying the full sleep in the last loop iteration -- a tiny saving given the small wait timeout

<details> <summary>suggested diff </summary>

diff --git a/test/functional/interface_http.py b/test/functional/interface_http.py
index 906c2f891b..b9caa5a197 100755
--- a/test/functional/interface_http.py
+++ b/test/functional/interface_http.py
@@ -763,12 +763,12 @@ class HTTPBasicsTest (BitcoinTestFramework):
         # server behavior because different platforms (macos in particular)
         # like to open and close the TCP window size based on heuristics
         # out of our control, and delay transmission when windows get too small.
-        flood_open = True
+        flood_stop = threading.Event()

         def send_flood(self, conn):
             sent_total = 0
             blocked = False
-            while flood_open:
+            while not flood_stop.is_set():
                 try:
                     sent = conn.conn.sock.send(flood)
                     sent_total += sent
@@ -781,7 +781,7 @@ class HTTPBasicsTest (BitcoinTestFramework):
                 if sent_total > len(flood) * 10:
                     # Don't use AssertionError here or it'll get excepted below
                     raise Exception(f"Client sent too much data: {sent_total}")
-                time.sleep(0.05)
+                flood_stop.wait(0.05)

         executor = concurrent.futures.ThreadPoolExecutor(max_workers=1)
         flood_thread = executor.submit(
@@ -831,7 +831,7 @@ class HTTPBasicsTest (BitcoinTestFramework):
         # already-passed verdict into a spurious TimeoutError. If the flood
         # thread hit its own assertion (server never throttled), result()
         # re-raises it here.
-        flood_open = False
+        flood_stop.set()
         flood_thread.result()
         executor.shutdown(wait=True)

</details>

pinheadmz commented at 11:32 AM on September 25, 2026:

Interesting suggestion! I'll try it out

in test/functional/interface_http.py:783 in b481e99e30

 825 | +                    if not blocked:
 826 | +                        blocked = True
 827 | +                        self.log.debug(f"Client socket blocked after sending {sent_total}")
 828 | +                if sent_total > len(flood) * 10:
 829 | +                    # Don't use AssertionError here or it'll get excepted below
 830 | +                    raise Exception(f"Client sent too much data: {sent_total}")

winterrdog commented at 8:52 PM on September 24, 2026:

nit: same here. i think we can remove the ambiguity:

                    raise Exception(f"Client sent too much data: {sent_total} bytes")

maflcko commented at 9:51 AM on September 25, 2026:

nit: Not too important, but I find the nested checks and different exception types, with catching a bit confusing. Also, "Client sent too much data" doesn't sound too helpful to indicate that a block did not occur.

Maybe just a plain:

assert_greater_than_or_equal(len(flood) * 10, sent_total);  # block should occur earlier

or (if you insist on hand-written msgs):

                assert sent <= len(flood) * 10, (
                    f"Server accepted {sent} bytes of pipelined data while a "
                    "request was still in flight: the receive buffer is not throttled")

(to minimize the diff)

But not important, just a nit.

Also, the comment is wrong, because send_flood is in a background thread without an except?

<!--

pinheadmz commented at 11:19 AM on September 25, 2026:

ok, reverting this

pinheadmz commented at 11:24 PM on September 25, 2026:

need to keep a try/finally though to close the background thread

winterrdog commented at 8:54 PM on September 24, 2026: contributor

approach ACK

winterrdog commented at 11:06 PM on September 24, 2026: contributor

reply-to: #36303 (comment)

And then yeah, its hard to pick constants for how long it should take for something not to happen. If the server code is broken and a ci machine is so slow it takes 6 seconds to read data from a socket then we'll have a false positive. I'd be happy bumping that to 10 or 5 * TIMEOUT_FACTOR or something? It just means safe/patched servers will sit in the test for that long before passing.

On the other end (5 minutes) I observed some CI runs that false-failed because the TCP was so slow it took a minute for the throttle to kick in at all. Again, could be a role for TIMEOUT_FACTOR.

Could borrow the approach @maflcko wrote in #36324

initially, i did think about polling faster at the beginning and only slowing down once things start to pause, for instance, checking every 250ms while total is still increasing, and only falling back to a longer wait once it stops changing. so, we could catch the stall sooner instead of always waiting out the entire fixed interval. it would save a few seconds in the fast case like in cases of local testing

but i think wait_until is the better call here: it is the same pattern check_slow_read_throttle() uses in the upcoming #36324, so this file would not end up with 2 different ways of waiting on the debug log, and CI-speed differences get handled by one shared setting (--timeout-factor)

DrahtBot renamed this:
~~http: Log bytes received from client, use to replace recieve-throttle regression test~~
http: Log bytes received from client, use to replace receive-throttle regression test
on Sep 25, 2026

pinheadmz force-pushed on Sep 25, 2026

pinheadmz commented at 11:26 PM on September 25, 2026: member

push to 5b4c945d6f933d857f8dcf479bd09c7d583c5fce

include suggestions from @maflcko and @winterrdog, unwrapping wait_until, using threading.Event() and clearing up some log lines.

test: assert HTTP receive throttle from server-side log

Rewrite check_pipelined_data_is_throttled() to stop inferring server
behavior from client-side send() results.

493850c4c4

pinheadmz force-pushed on Sep 25, 2026

pinheadmz commented at 11:38 PM on September 25, 2026: member

push to 493850c4c4734acce0f75d1efcffb3868d4235fc

remove unused capture group in the regex matcher

DrahtBot added the label CI failed on Sep 25, 2026

DrahtBot removed the label CI failed on Sep 26, 2026

winterrdog commented at 9:12 PM on September 27, 2026: contributor

tACK 493850c4c4734acce0f75d1efcffb3868d4235fc

successfully built and tested on: FreeBSD 15.0/clang++-19/x86_64

reply-to: #36303#issue-5518981709

These are optional debug lines in a worst-case scenario, but reviewers can discuss rate-limiting that log activity if we're afraid it's too much.

for now, i think we can skip rate-limiting this. normal traffic only produces one log line per request, and the flood test's worst case (a single ~32MB request) tops out at around 600-700 lines in well under half a second (tried it out with this script). that does not seem too noisy for an opt-in debug category :)

if, indeed, we get empirical evidence that this has become a problem, a simple fix i can think of right now would be to place the logging behind a tiny per-client interval, for instance, only emit the debug log if at least 100ms have passed since the last one for that client

DrahtBot requested review from davidgumberg on Sep 27, 2026

hebasto commented at 4:23 PM on September 29, 2026: member

FWIW, https://github.com/hebasto/bitcoin-core-nightly/pull/369.

davidgumberg commented at 6:36 PM on September 29, 2026: contributor

crtACK https://github.com/bitcoin/bitcoin/commit/493850c4c4734acce0f75d1efcffb3868d4235fc

in test/functional/interface_http.py:781 in 493850c4c4

 823 | +                    self.log.debug(f"Client sent {sent} bytes (total {sent_total})")
 824 | +                except BlockingIOError:
 825 | +                    if not blocked:
 826 | +                        blocked = True
 827 | +                        self.log.debug(f"Client socket blocked after sending {sent_total} bytes")
 828 | +                if sent_total > len(flood) * 10:

ismaelsadeeq commented at 4:32 AM on October 5, 2026:

In "test: assert HTTP receive throttle from server-side log"

non-blocking: We could make the verdict entirely bitcoind-based by letting the client be a dumb flooder and, after wait_until(progress_stalled), asserting the server's received-byte counter stayed reasonable (total < len(flood)*10).

ismaelsadeeq commented at 4:54 AM on October 5, 2026: member

Code review ACK 493850c4c4734acce0f75d1efcffb3868d4235fc Ran interface_http.py ×200 on: macOS 26.6.2 (25G83), arm64 (Apple M2 Pro, Mac14, - Xcode 26.1 (17B55), Apple clang 17.0.0, SDK 26.1

check_pipelined_data_is_throttled passed every time, couldn't reproduce the intermittent failure. My config differs from the failing nightly runner (run 34438869701 (https://github.com/hebasto/bitcoin-core-nightly/actions/runs/34438869701/job/102749511737)), which was macOS 26.5.2 / Xcode 27, I'm on a newer macOS but an older Xcode, so I can't say whether it's toolchain or OS-specific .

A few non-blocking notes: -

The revert diff disables the throttle, so it confirms the test catches unthrottling. IIUC the original intermittent failure was the small one-read window × macOS TCP timing, and a ~64 KB leak would plateau well under the fail threshold.

The OP description is mostly context (the macOS TCP behavior). It'd aid review to also state the change itself: i.e we add a per-read debug log in HTTPRemoteClient::Receive() and some context on why their etc, and that we rewrites the test to flood the connection and detect the stall from that log.
The approach relies on the log being emitted per socket read before request parsing, so the counter tracks bytes drained off the socket even when no request completes. If it moved to request-completion/dispatch, a never-completing flood would emit nothing and the counter couldn't observe an unbounded read. Worth a comment noting this placement is intentional load-bearing. (It seems in the test prevent that, by the total > 0 check though).

sedited requested review from maflcko on Oct 5, 2026

achow101 commented at 9:43 PM on October 5, 2026: member

ACK 493850c4c4734acce0f75d1efcffb3868d4235fc

achow101 merged this on Oct 5, 2026

achow101 closed this on Oct 5, 2026

fanquake referenced this in commit 2475cc8100 on Oct 6, 2026

fanquake referenced this in commit f8bd7f0f51 on Oct 6, 2026

fanquake removed the label Needs Backport (32.x) on Oct 6, 2026

fanquake commented at 2:01 PM on October 6, 2026: member

Backported to 32.x in #36427.