Skip to content

Commit d4bd070

Browse files
committed
Drop the unreachable arms of the busy-page backoff
Nothing on the read path sends Retry-After: the API answers with a bare FastAPI HTTPException and the ingress rate limiter adds no headers either, so that branch was shaping a delay no server asks for. The ceiling was unreachable too — four doublings from half a second top out at four, jitter included. What is left is the backoff itself. Name the jitter fraction rather than spelling the band inline, and cover the growth the constants describe. The give-up test now exhausts the budget on a later page, so it also pins that an already delivered chunk stands. Signed-off-by: Honglin Cao <hocao@nvidia.com>
1 parent 0fc124d commit d4bd070

2 files changed

Lines changed: 44 additions & 38 deletions

File tree

‎centml/sdk/api.py‎

Lines changed: 18 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -33,12 +33,15 @@
3333
# caller's events within this generous margin of the boundary can be re-delivered.
3434
LOG_DEDUP_RETENTION_MS = 300_000
3535
# The log read path is rate limited upstream on a bucket shared by every caller, and the
36-
# API reports a saturated bucket the same way it reports a sick store: HTTP 503. The
37-
# budget spans a few seconds, long enough to outlast a bucket refill without looking hung.
36+
# API reports a saturated bucket the same way it reports a sick store: HTTP 503. Doubling
37+
# from half a second spends about seven seconds over the budget below — long enough to
38+
# outlast a bucket refill without looking hung.
3839
LOG_BUSY_STATUS = 503
3940
LOG_RETRY_ATTEMPTS = 5
4041
LOG_RETRY_BASE_SECONDS = 0.5
41-
LOG_RETRY_MAX_SECONDS = 8.0
42+
# Fraction of each backoff to vary it by: the bucket is shared, so clients backing off in
43+
# lockstep would re-collide on it every round.
44+
LOG_RETRY_JITTER = 0.25
4245

4346

4447
def _with_busy_retry(fetch_page):
@@ -51,14 +54,8 @@ def _with_busy_retry(fetch_page):
5154
except ApiException as exc:
5255
if exc.status != LOG_BUSY_STATUS:
5356
raise
54-
retry_after = exc.headers.get("Retry-After") if exc.headers else None
55-
if retry_after is not None and retry_after.isdigit():
56-
delay = min(float(retry_after), LOG_RETRY_MAX_SECONDS)
57-
else:
58-
# jitter: the bucket is shared, so unjittered clients re-collide on it
59-
backoff = min(LOG_RETRY_BASE_SECONDS * 2**attempt, LOG_RETRY_MAX_SECONDS)
60-
delay = backoff * (0.75 + random.random() * 0.5)
61-
time.sleep(delay)
57+
backoff = LOG_RETRY_BASE_SECONDS * 2**attempt
58+
time.sleep(backoff * (1 + random.uniform(-LOG_RETRY_JITTER, LOG_RETRY_JITTER)))
6259
# the last attempt propagates whatever it raises
6360
return fetch_page()
6461

@@ -457,17 +454,16 @@ def fetch_logs(
457454
in ascending (timestamp, id) order.
458455
459456
A page request the store answers as busy (HTTP 503) is retried with
460-
exponential backoff and jitter, honouring Retry-After when the server
461-
sends one; the anchor survives the retry, so an upstream rate limit costs
462-
a pause rather than the stream.
463-
464-
If a page request fails for any other reason, or the retries run out, the
465-
iterator raises and, like any generator, cannot be resumed — but every
466-
chunk already yielded is complete and none is left half-built. Resume
467-
with a new fetch_logs whose start_time is the
468-
last delivered event's timestamp: bounds are inclusive, so the only lines
469-
delivered again are the ones sharing that millisecond, which the caller
470-
already holds.
457+
exponential backoff and jitter; the anchor survives the retry, so an
458+
upstream rate limit costs a pause rather than the stream.
459+
460+
If a page request fails for any other reason, or the retries run out,
461+
the iterator raises and, like any generator, cannot be resumed — but
462+
every chunk already yielded is complete and none is left half-built.
463+
Resume with a new fetch_logs whose start_time is the last delivered
464+
event's timestamp: bounds are inclusive, so the only lines delivered
465+
again are the ones sharing that millisecond, which the caller already
466+
holds.
471467
"""
472468
if not 1 <= chunk_size <= MAX_LOG_PAGE_LINES:
473469
raise ValueError(

‎tests/test_sdk_api.py‎

Lines changed: 26 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,8 @@
1717
from centml.sdk.api import (
1818
LOG_DEDUP_RETENTION_MS,
1919
LOG_RETRY_ATTEMPTS,
20+
LOG_RETRY_BASE_SECONDS,
21+
LOG_RETRY_JITTER,
2022
MAX_LOG_PAGE_LINES,
2123
CentMLClient,
2224
DeploymentLogSession,
@@ -1031,42 +1033,50 @@ def test_fetch_logs_survives_a_busy_store_without_losing_its_anchor():
10311033

10321034
def test_fetch_logs_gives_up_on_a_busy_store_after_the_retry_budget():
10331035
api = MagicMock()
1034-
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=503)
1036+
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [
1037+
_log_page(_log_event("1-a", 1000))
1038+
] + [ApiException(status=503)] * LOG_RETRY_ATTEMPTS
10351039
client = CentMLClient(api)
10361040

1041+
stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=1)
1042+
assert [e.id for e in next(stream)] == ["1-a"]
1043+
10371044
with patch("centml.sdk.api.time.sleep") as sleep:
10381045
with pytest.raises(ApiException):
1039-
next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000))
1046+
next(stream)
10401047

1041-
assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == LOG_RETRY_ATTEMPTS
1048+
# The whole budget goes on the one page, and the chunk already delivered stands.
10421049
assert sleep.call_count == LOG_RETRY_ATTEMPTS - 1
10431050

10441051

1045-
def test_fetch_logs_does_not_retry_a_request_the_store_rejects():
1052+
def test_fetch_logs_backs_off_further_on_each_busy_answer():
10461053
api = MagicMock()
1047-
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=404)
1054+
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ApiException(status=503)] * (
1055+
LOG_RETRY_ATTEMPTS - 1
1056+
) + [_log_page()]
10481057
client = CentMLClient(api)
10491058

10501059
with patch("centml.sdk.api.time.sleep") as sleep:
1051-
with pytest.raises(ApiException):
1052-
next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000))
1060+
assert _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) == []
10531061

1054-
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once()
1055-
sleep.assert_not_called()
1062+
waited = [call.args[0] for call in sleep.call_args_list]
1063+
assert len(waited) == LOG_RETRY_ATTEMPTS - 1
1064+
for attempt, seconds in enumerate(waited):
1065+
nominal = LOG_RETRY_BASE_SECONDS * 2**attempt
1066+
assert nominal * (1 - LOG_RETRY_JITTER) <= seconds <= nominal * (1 + LOG_RETRY_JITTER)
10561067

10571068

1058-
def test_fetch_logs_waits_the_retry_after_the_store_asks_for():
1059-
busy = ApiException(status=503)
1060-
busy.headers = {"Retry-After": "2"}
1069+
def test_fetch_logs_does_not_retry_a_request_the_store_rejects():
10611070
api = MagicMock()
1062-
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [busy, _log_page()]
1071+
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=404)
10631072
client = CentMLClient(api)
10641073

10651074
with patch("centml.sdk.api.time.sleep") as sleep:
1066-
assert _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) == []
1075+
with pytest.raises(ApiException):
1076+
next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000))
10671077

1068-
# Honoured verbatim, not jittered: the server named the delay.
1069-
sleep.assert_called_once_with(2.0)
1078+
api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once()
1079+
sleep.assert_not_called()
10701080

10711081

10721082
def test_fetch_logs_is_lazy_until_the_first_next():

0 commit comments

Comments
 (0)