Summary
rate_limit_sni_queue fails intermittently. The assertion that fails is the test's own
precondition check, not the behaviour it exists to verify: it cannot prove it reached the
queue path, because reaching that path depends on wall clock sleeps racing a live TLS
handshake.
Observed
AuTest 2of4, 1 failed out of 150 tests. Every other assertion in the run passed,
including the one the test was written for:
file .../ts/log/traffic.out : a connection was queued - Failed
Reason: did not contain expression: "Queueing the VC"
file .../ts/log/traffic.out : the active-slot counter must not underflow and abort ATS - Passed
Run: rate_limit SNI queue accounting: Passed
Test : Checking that ReturnCode == 0 - Passed
So ATS did not abort, the traffic ran clean, and the diags log was error free. Only
"did I manage to queue a connection at all" failed.
It is load dependent rather than deterministic: the same shard passes on other pull
requests and fails repeatedly on one that adds an AuTest, which shifts the shard slice
and changes which tests share a worker.
Cause
tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh choreographs the
race with sleep:
${OSSL} <"$fifo" & # holder takes the single slot
sleep 3 # "let the holder reserve the one slot"
run_for 0.3 sh -c "${OSSL} </dev/null" # second connection, must queue
sleep 2 # >= 2 sweep periods
exec 3>&- # release the holder
With limit: 1 and a queue admitting one more, "Queueing the VC" is logged only if the
second openssl s_client reaches the limiter while the holder still owns the slot. That
second connection is given a 0.3 second window before run_for kills it.
On a loaded runner that window is not reliable. If the handshake is delayed past 0.3s the
connection is killed before it reaches the limiter, nothing is queued, and the expression
never appears. The holder's sleep 3 has the same exposure from the other side: if the
holder is slow to establish, the second connection arrives before the slot is taken and
is served rather than queued.
Both failures look identical in the log, and neither indicates a problem with the
accounting fix from #13406 that the test guards.
Suggested fix
Make the precondition an observation rather than a timer. Options, roughly in order of
preference:
- Have the client wait until the holder's connection is established before launching the
second one, rather than sleeping a fixed 3 seconds.
- Give the second connection a window long enough to survive a loaded runner, since
run_for 0.3 is the tightest constraint in the script and the one most likely to lose.
- Failing both, treat "the queue path was not reached" as a skip rather than a failure,
so the test still reports honestly without failing a build for a precondition it could
not establish. The _active <= _limit assertion is the one that must stay hard.
The test itself is worth keeping. It guards a real crash from #13406, and that assertion
is passing; it is only the setup that is fragile.
Summary
rate_limit_sni_queuefails intermittently. The assertion that fails is the test's ownprecondition check, not the behaviour it exists to verify: it cannot prove it reached the
queue path, because reaching that path depends on wall clock sleeps racing a live TLS
handshake.
Observed
AuTest 2of4, 1 failed out of 150 tests. Every other assertion in the run passed,
including the one the test was written for:
So ATS did not abort, the traffic ran clean, and the diags log was error free. Only
"did I manage to queue a connection at all" failed.
It is load dependent rather than deterministic: the same shard passes on other pull
requests and fails repeatedly on one that adds an AuTest, which shifts the shard slice
and changes which tests share a worker.
Cause
tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.shchoreographs therace with
sleep:With
limit: 1and a queue admitting one more,"Queueing the VC"is logged only if thesecond
openssl s_clientreaches the limiter while the holder still owns the slot. Thatsecond connection is given a 0.3 second window before
run_forkills it.On a loaded runner that window is not reliable. If the handshake is delayed past 0.3s the
connection is killed before it reaches the limiter, nothing is queued, and the expression
never appears. The holder's
sleep 3has the same exposure from the other side: if theholder is slow to establish, the second connection arrives before the slot is taken and
is served rather than queued.
Both failures look identical in the log, and neither indicates a problem with the
accounting fix from #13406 that the test guards.
Suggested fix
Make the precondition an observation rather than a timer. Options, roughly in order of
preference:
second one, rather than sleeping a fixed 3 seconds.
run_for 0.3is the tightest constraint in the script and the one most likely to lose.so the test still reports honestly without failing a build for a precondition it could
not establish. The
_active <= _limitassertion is the one that must stay hard.The test itself is worth keeping. It guards a real crash from #13406, and that assertion
is passing; it is only the setup that is fragile.