diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py index 59042752620..15d332f0a69 100644 --- a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py @@ -1,9 +1,16 @@ ''' -Regression test for a queue-accounting balance bug in the rate_limit SNI limiter: a -queued connection never reserves a slot, but its VCONN_CLOSE unconditionally releases -one, so a queued connection that closes underflows the active-slot counter and the next -reserve() trips a release assertion, aborting the server. ATS must survive the queue -churn. +Regression test for the rate_limit SNI limiter's queue accounting. A queued connection never +reserves a slot, so the sweep must reserve one before resuming it and a close must release +only a slot the connection owns. When the sweep resumes a queued connection while the limiter +is still full, the holder's close lands the active-slot counter on zero, the resumed +connection's close releases a slot it never held and wraps the counter below zero, and the +next reserve() trips a release assertion that aborts the server. ATS must survive the queue +churn without the counter wrapping. + +The client drives resume-then-close rather than closing a connection while it is parked, +because ATS does not read the socket while the ClientHello hook is invoked: a FIN from a +parked client is invisible until the sweep reenables the VC. The close-while-queued branch +is out of scope for this test and cannot be reached from a client. ''' # Licensed to the Apache Software Foundation (ASF) under one # or more contributor license agreements. See the NOTICE file @@ -69,17 +76,32 @@ def _configure_trafficserver(self) -> None: 'proxy.config.diags.debug.tags': 'rate_limit', }) - # The queue path is reached... + # The queue path is reached and the sweep resumes the queued connection once the + # holder has released its slot... ts.Disk.traffic_out.Content = Testers.ContainsExpression('Queueing the VC', 'a connection was queued') - # ...and the active-slot counter never underflows into the release assertion. Match - # both the specific assertion (pins the failure to this bug) and the generic abort. + ts.Disk.traffic_out.Content += Testers.ContainsExpression( + 'Enabling queued VC', 'the sweep resumed the queued connection into a reserved slot') + # ...nothing is turned away: with one holder and a queue of one, a rejection means the + # holder never released and the probe hit a full queue, so the release path went + # unexercised... + ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + 'Rejecting connection', 'no connection is rejected; the holder must release its slot') + # ...and the active-slot counter never underflows. free() logs the counter after + # dropping the lock, so a concurrent reserve() can legitimately make a release read back + # as 1; only a wrapped counter is a defect, and an unmatched decrement of a uint32 at + # limit 1 is unmistakable -- it reads 4294967295, never a small number. + ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + r'Releasing a slot, active entities == [0-9]{4,}', 'a release must never wrap the counter') ts.Disk.traffic_out.Content += Testers.ExcludesExpression( '_active <= _limit|received signal', 'the active-slot counter must not underflow and abort ATS') def _configure_client(self, tr: 'TestRun') -> None: ts = self._ts client = os.path.join(Test.TestDirectory, 'rate_limit_sni_queue_client.sh') - tr.Processes.Default.Command = f'bash {client} 127.0.0.1 {ts.Variables.ssl_port} rate.limited.com' + # The client paces itself on the plugin's debug lines in traffic.out, so it needs the + # path rather than a guess at how long each step takes. + tr.Processes.Default.Command = ( + f'bash {client} 127.0.0.1 {ts.Variables.ssl_port} rate.limited.com {ts.Disk.traffic_out.AbsPath}') tr.Processes.Default.ReturnCode = 0 tr.Processes.Default.StartBefore(ts) tr.Processes.Default.Streams.stdout = Testers.ContainsExpression( diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh index 0ce7e56f3b1..27c995b92df 100644 --- a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh @@ -20,59 +20,183 @@ # and check that the active-slot counter stays balanced and the server survives. # # 1. holder completes its handshake and holds the single slot (counter = 1); -# 2. one connection enqueues because the slot is full, then closes while parked; -# 3. the sweep reserves a slot and resumes a queued connection; -# 4. the holder is closed and releases its slot; +# 2. one connection enqueues because the slot is full and stays parked at the ClientHello hook; +# 3. the sweep runs while the slot is still held and must leave the queued connection parked; +# 4. the holder is closed and releases its slot; the next sweep reserves that slot and resumes +# the queued connection, which is then closed and releases the slot it now owns; # 5. a probe connection reserves the freed slot. # -# Against the plugin before 508c1bea26 this aborts the server: the sweep resumed a queued -# connection without a reservation, whose close then decremented the counter unmatched until it -# wrapped and reserve() tripped TSReleaseAssert(_active <= _limit). The test asserts the counter -# never wraps and no signal is logged, so it pins that fix as well as this change. +# The accounting under test: a queued connection holds no slot, so the sweep must reserve one +# before resuming it. A resume without that reservation aborts the server, because the holder's +# close lands the counter on zero and the resumed connection's close, releasing a slot it never +# held, wraps it below zero, so the probe's reserve() trips TSReleaseAssert(_active <= _limit). +# Step 4 asserts the reservation directly and fails there, naming the defect rather than the crash +# it leads to. The test's traffic.out testers reject that wrap and that abort however they arise, +# and stay the backstop for both. # -# args: host port sni +# The connection is resumed and then closed, never closed while parked, because a client cannot +# close a parked connection as far as ATS is concerned: while the ClientHello hook is invoked ATS +# does not read the socket, so a FIN sits in the kernel until the sweep reenables the VC. The +# close-while-queued branch of sni_limiter.cc is therefore out of scope here and cannot be driven +# from a client, so a "closes while parked" step would only resolve to the resume-then-close path +# this script already drives. +# +# Every step waits for the plugin's own debug line in traffic.out rather than sleeping for a +# guessed interval, so a loaded runner cannot let a connection miss the holder and skip the queue +# path unnoticed. Every connection reads stdin from a FIFO that never delivers data, and is ended +# with kill -TERM on openssl's own PID. +# Neither the moment a connection opens nor the moment it closes is left to s_client: how it +# reacts to EOF on stdin differs between OpenSSL and LibreSSL, so a connection that must stay up +# is given stdin that never becomes readable, and one that must go is killed outright. The plugin +# only needs the VCONN_CLOSE that the resulting FIN produces. +# +# args: host port sni traffic_out set -u host="$1" port="$2" sni="$3" +traffic_out="$4" -OSSL="openssl s_client -connect ${host}:${port} -servername ${sni} -quiet -no_ign_eof" - -# Run a command in the background and terminate it after a deadline. coreutils "timeout" is not -# available everywhere (notably macOS), so do it with sleep and kill. -run_for() { - deadline="$1" - shift - "$@" & - target=$! - ( - sleep "${deadline}" - kill -TERM "${target}" 2>/dev/null - ) & -} +OSSL="openssl s_client -connect ${host}:${port} -servername ${sni} -quiet" + +# Ceiling per step. It only bounds a broken run; a healthy one moves on as soon as the line +# appears. +WAIT_LIMIT=30 + +holder="" +queued="" +probe="" -# 1. Holder: hold the single slot. Its stdin is a FIFO kept open on fd 3, so we end the -# holder deterministically in step 4 (closing fd 3 -> EOF -> clean TLS close -> FIN). +# Shared stdin for every connection: a FIFO held open read-write on fd 3 that nothing ever +# writes to, so reads block and polls stay idle until the process is killed. Opening it +# read-write does not block, and the connections inherit fd 3 rather than opening the path, +# so the directory can go straight away. fifo_dir="$(mktemp -d "${TMPDIR:-/tmp}/rl_holder.XXXXXX")" -fifo="${fifo_dir}/fifo" -mkfifo "$fifo" -${OSSL} <"$fifo" >/dev/null 2>&1 & -exec 3<>"$fifo" +mkfifo "${fifo_dir}/fifo" +exec 3<>"${fifo_dir}/fifo" rm -rf "$fifo_dir" -sleep 3 # let the holder reserve the one slot -# 2. One queued connection: enqueues because the slot is full, then closes while still parked -# at the ClientHello hook. -run_for 0.3 sh -c "${OSSL} /dev/null 2>&1" -sleep 2 # >= 2 sweep periods (300ms each), so the sweep runs while the connection is queued +# Poll traffic.out until the fixed string has appeared at least count times. Diags serialises +# each debug line and flushes it whole, so polling can never see a half-written line and a line +# is visible as soon as the plugin emits it. On timeout, fail loudly with what was expected and +# what the log holds so the sandbox is diagnosable. +wait_for() { + needle="$1" + count="$2" + end=$((SECONDS + WAIT_LIMIT)) + while :; do + seen=$(grep -c -F -- "$needle" "$traffic_out" 2>/dev/null || true) + if [ "${seen:-0}" -ge "$count" ]; then + return 0 + fi + if [ "$SECONDS" -ge "$end" ]; then + echo "timed out after ${WAIT_LIMIT}s waiting for occurrence ${count} of '${needle}' (saw ${seen:-0})" >&2 + echo "--- tail of ${traffic_out}:" >&2 + tail -n 20 "$traffic_out" >&2 + exit 1 + fi + sleep 0.1 + done +} + +# Close a connection by killing openssl itself. Escalate to KILL rather than waiting forever: +# a TERM-immune s_client would otherwise stall the run until autest's process timeout, turning a +# seconds-long failure into a ten-minute one. +# +# The whole body is redirected because the shell announces a signal-killed background job on the +# script's stderr as it reaps it ("Terminated: 15"), at whatever command happens to be running -- +# redirecting the wait alone does not catch it. That noise would sit in stream.stderr.txt next to +# this script's real diagnostics, so keep it out and report an escalation on the saved fd instead. +end_connection() { + exec 4>&2 + { + kill -TERM "$1" 2>/dev/null || true + waited=0 + while kill -0 "$1" 2>/dev/null; do + if [ "$waited" -ge 30 ]; then + echo "pid $1 ignored TERM after 3s; escalating to KILL" >&4 + kill -KILL "$1" 2>/dev/null || true + break + fi + waited=$((waited + 1)) + sleep 0.1 + done + wait "$1" || true + } 2>/dev/null + exec 4>&- +} + +# Give every child still running the same bounded teardown on the way out, including on an early +# exit from a wait_for timeout or a failed assertion below. A TERM-immune s_client would otherwise +# outlive the run still holding the inherited FIFO and a live TLS connection into ATS, and leak +# into the next test in the shard. Each pid is cleared as it is reaped, so neither this trap nor a +# later step can signal a pid the kernel has since handed to an unrelated process. +cleanup() { + local pid + + for pid in ${holder} ${queued} ${probe}; do + end_connection "$pid" + done +} +trap cleanup EXIT + +# 1. Holder: take the single slot. +${OSSL} <&3 >/dev/null 2>&1 & +holder=$! +wait_for 'Reserving a slot, active entities == 1' 1 + +# 2. Queued connection: the slot is full, so it is parked at the ClientHello hook. +${OSSL} <&3 >/dev/null 2>&1 & +queued=$! +wait_for 'Queueing the VC, we are at capacity' 1 + +# 3. Let the sweep (every 300ms) run while the slot is still held. This is a lower bound, not a +# race: a correct sweep leaves the connection parked, which produces no line to wait for, +# and a slower runner only gives it more sweeps. A sweep that dequeues here is the bug this +# test pins; step 4 is where that is caught, so there is nothing to wait for now. +sleep 1 + +# 4. End the holder. The sweep then reserves the freed slot and resumes the queued connection; +# ending that connection must release exactly the slot it was granted. The waits key on the +# release line alone, not its value, so a wrapped counter still lets the probe run and trip +# the assertion the test guards; the value is checked by the test's traffic.out testers. +end_connection "$holder" +holder="" +wait_for 'Releasing a slot, active entities ==' 1 +wait_for 'Enabling queued VC' 1 + +# That wait counts resumes, so by itself it is equally satisfied by a resume the sweep emitted +# back in step 3 while the limiter was still full -- the one event this test exists to reject. +# Assert the invariant rather than the count: the sweep reserves a slot and then logs the resume +# from the same continuation, so a legitimate resume always has the sweep's own reservation ahead +# of it in program order, never subject to which thread logs first. A resume that reserved nothing +# leaves only the holder's reservation ahead of it, which is what this rejects. Ordering the resume +# against the holder's release would be a race instead, because free() logs after dropping the +# lock. It is checked here rather than left to the counter wrap downstream, so a resume that skips +# the reservation without going on to wrap the counter is still caught, and is named where it +# happens. +resume_line=$(grep -n -F -- 'Enabling queued VC' "$traffic_out" | head -n 1 | cut -d: -f1) +reserved_before=$(head -n "${resume_line:-0}" "$traffic_out" | grep -c -F -- 'Reserving a slot, active entities ==' || true) +if [ "${reserved_before:-0}" -lt 2 ]; then + echo "the sweep resumed the queued connection without reserving a slot for it:" \ + "${reserved_before:-0} reservation(s) logged before the resume, expected the holder's and the sweep's" >&2 + exit 1 +fi -# 4. End the holder, releasing its slot. -exec 3>&- # close the FIFO write end -> holder sees EOF -> clean TLS close (FIN) -sleep 2 +# The kill can land before ATS has acted on the reenable, or mid-handshake. Either way the read +# error closes the VC and the VCONN_CLOSE hook still fires, so the release below is not a race. +end_connection "$queued" +queued="" +wait_for 'Releasing a slot, active entities ==' 2 # 5. Probe: reserve() must succeed against a balanced counter rather than tripping the -# TSReleaseAssert(_active <= _limit) that a wrapped counter causes. -run_for 2 sh -c "${OSSL} /dev/null 2>&1" -sleep 3 +# TSReleaseAssert(_active <= _limit) that a wrapped counter causes. This is the third +# reservation: holder, sweep, probe. +${OSSL} <&3 >/dev/null 2>&1 & +probe=$! +wait_for 'Reserving a slot, active entities == 1' 3 +end_connection "$probe" +probe="" +wait_for 'Releasing a slot, active entities ==' 3 echo "rate_limit-queue-crash-done"