From 59ff8dbff5c79084ba8c8f689bea4cfb2b0d9287 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Tue, 15 Sep 2026 11:00:34 -0400 Subject: [PATCH 01/22] Add iter_deployment_logs lazy streaming generator Stream a revision's logs oldest-first with bounded held state: pages are fetched as the iterator is consumed, per-pod anchors are trimmed to the server's re-delivery window, and pod=None merges every pod via a (timestamp, id) watermark. follow=True keeps tailing, re-listing the revision's pods so replacement pods join the merge; a pod silent past LOG_MERGE_HOLD_POLLS poll intervals stops gating the watermark. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 106 ++++++++++++++++- tests/test_sdk_api.py | 256 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 360 insertions(+), 2 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index afa8b26..33aa69b 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -1,7 +1,9 @@ +import time from bisect import insort from contextlib import contextmanager -from dataclasses import dataclass -from typing import List, Optional, Union +from dataclasses import dataclass, field +from heapq import heappop, heappush +from typing import Dict, Iterator, List, Optional, Union import platform_api_python_client from platform_api_python_client import ( @@ -29,6 +31,12 @@ # The server re-delivers a ~15s look-behind window on fetch-newer requests; only the # caller's events within this generous margin of the boundary can be re-delivered. LOG_DEDUP_RETENTION_MS = 300_000 +# In a followed multi-pod merge, a pod that stops logging holds back the merged +# stream at most this many poll intervals before its peers' buffers flush past it. +LOG_MERGE_HOLD_POLLS = 2 +# How often a followed multi-pod merge re-lists the revision's pods to pick up +# replacements and scale-ups. +LOG_POD_REFRESH_SECONDS = 15.0 def _recent_anchor(events: list) -> list: @@ -53,6 +61,17 @@ class DeploymentLogEvent: pod: str +@dataclass +class _PodLogTail: + """Per-pod cursor for iter_deployment_logs: the trimmed dedup window it holds, + the newest timestamp it has fetched (its merge-watermark contribution), and + when it last produced data (monotonic; gates the silent-pod hold).""" + + last_data: float + held: List[DeploymentLogEvent] = field(default_factory=list) + frontier: int = -1 + + class CentMLClient: def __init__(self, api): self._api: platform_api_python_client.EXTERNALApi = api @@ -334,6 +353,89 @@ def get_deployment_logs_range( merged.sort(key=lambda event: event.id) return merged + # pylint: disable=R0917 + def iter_deployment_logs( + self, + deployment_id: int, + revision_number: int, + pod: Optional[str] = None, + start_time: Optional[int] = None, + follow: bool = False, + poll_interval: float = 2.0, + max_lines: int = MAX_LOG_PAGE_LINES, + ) -> Iterator[DeploymentLogEvent]: + """Stream a revision's logs lazily, oldest first, each line exactly once, + each event carrying its pod name. Pages are fetched as the iterator is + consumed, and the state held per pod is trimmed to the server's + re-delivery window, so memory stays bounded however many lines stream by. + + pod=None merges every pod of the revision into one stream ordered by + (timestamp, id); pods are buffered and emitted up to the merge watermark + (the oldest frontier any pod has fetched to). start_time (epoch ms, + inclusive) bounds the beginning; None reads from the start of the log + window. follow=False returns once every pod is caught up. follow=True + keeps tailing: caught-up pods are re-polled every poll_interval seconds + and the revision's pod list is re-read every LOG_POD_REFRESH_SECONDS so + replacement pods join the merge as they first log. While following, a + pod silent for LOG_MERGE_HOLD_POLLS poll intervals stops gating the + watermark, so cross-pod ordering is best-effort beyond that bound; a + single-pod stream is always strictly ordered. + """ + initial_boundary = start_time - 1 if start_time else 0 + now = time.monotonic() + last_refresh = now + pods = [pod] if pod is not None else self.get_deployment_pods(deployment_id, revision_number) + tails: Dict[str, _PodLogTail] = {name: _PodLogTail(last_data=now) for name in pods} + pending: list = [] # min-heap of (timestamp, id, event) awaiting the watermark + + while True: + if follow and pod is None and time.monotonic() - last_refresh >= LOG_POD_REFRESH_SECONDS: + last_refresh = time.monotonic() + for name in self.get_deployment_pods(deployment_id, revision_number): + if name not in tails: + tails[name] = _PodLogTail(last_data=last_refresh) + + fetched_any = False + for name, tail in list(tails.items()): + page = self.get_deployment_logs( + deployment_id, revision_number, name, after=tail.held or initial_boundary, max_lines=max_lines + ) + if not page: + if not follow: + del tails[name] # caught up: stop gating the watermark on it + continue + fetched_any = True + tail.last_data = time.monotonic() + for raw in page: + event = DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=name) + if tail.held and event.id <= tail.held[-1].id: + # Late arrival inside the look-behind span: keep the held window + # id-ordered (id order == time order) so trimming stays correct. + insort(tail.held, event, key=lambda held_event: held_event.id) + else: + tail.held.append(event) + # Anchoring at start_time - 1 re-delivers the look-behind span below + # start_time; those ids must be held for dedup but never emitted. + if start_time is None or event.timestamp >= start_time: + heappush(pending, (event.timestamp, event.id, event)) + tail.held = _recent_anchor(tail.held) + tail.frontier = tail.held[-1].timestamp + + if follow: + hold_cap = LOG_MERGE_HOLD_POLLS * poll_interval + gating = [t.frontier for t in tails.values() if time.monotonic() - t.last_data <= hold_cap] + else: + gating = [t.frontier for t in tails.values()] + watermark = min(gating) if gating else None + while pending and (watermark is None or pending[0][0] <= watermark): + yield heappop(pending)[2] + + if not follow: + if not tails: + return + elif not fetched_any: + time.sleep(poll_interval) + def deployment_log_session( self, deployment_id: int, revision_number: int, pod: str, events: Optional[list] = None ) -> "DeploymentLogSession": diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index ab1c55d..c4434c4 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -633,3 +633,259 @@ def test_log_session_long_window_keeps_boundary_and_dedup_correct(): session.fetch_older() call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args assert call.kwargs["fetch_newer"] is False and call.kwargs["timestamp"] == 1 + + +class _FakeClock: + """Deterministic stand-in for time.monotonic/time.sleep in follow-mode tests.""" + + def __init__(self, max_sleeps=100): + self.now = 0.0 + self.sleeps = 0 + self._max_sleeps = max_sleeps + + def monotonic(self): + return self.now + + def sleep(self, seconds): + self.sleeps += 1 + if self.sleeps > self._max_sleeps: + raise TimeoutError("test exceeded its sleep budget") + self.now += seconds + + +def _clock_patches(clock): + return (patch("centml.sdk.api.time.monotonic", clock.monotonic), patch("centml.sdk.api.time.sleep", clock.sleep)) + + +def test_iter_deployment_logs_yields_first_page_before_fetching_the_next(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), + _log_page(_log_event("3-c", 3000)), + _log_page(), + ] + client = CentMLClient(api) + + stream = client.iter_deployment_logs(123, 2, pod="pod-a") + first = next(stream) + + assert first.id == "1-a" and first.pod == "pod-a" + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 1 + # The first fetch never passes an (invalid) empty anchor list: it is a bare + # int boundary reading from the head of the log window. + first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] + assert first_call.kwargs["fetch_newer"] is True and first_call.kwargs["timestamp"] == 0 + + assert [e.id for e in stream] == ["2-b", "3-c"] + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 3 + + +def test_iter_deployment_logs_terminates_when_caught_up_without_sleeping(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000)), + _log_page(), + ] + client = CentMLClient(api) + + with patch("centml.sdk.api.time.sleep") as sleep: + events = list(client.iter_deployment_logs(123, 2, pod="pod-a")) + + assert [e.id for e in events] == ["1-a"] + sleep.assert_not_called() + + +def _replaying_log_server(all_events, look_behind_ms=15_000): + """Mimic the server: newer-than-boundary lines up to max_lines, plus the + re-delivered look-behind span at and before the boundary (uncounted).""" + + def respond(**kwargs): + boundary = kwargs["timestamp"] + newer = [e for e in all_events if e.timestamp > boundary][: kwargs["max_lines"]] + gray = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] + return _log_page(*sorted(gray + newer, key=lambda e: e.id)) + + return respond + + +def test_iter_deployment_logs_does_not_livelock_on_gray_span_redelivery(): + # Regression: with a bare int boundary the re-delivered look-behind span keeps + # every page non-empty forever (measured against dev: 9 iterations of the same + # 7 gray lines before the naive port was declared wedged). The generator holds + # the trailing events, so the gray span dedupes away and the stream terminates. + all_events = [_log_event(f"{1000 + i:05d}-x", 1000 + i) for i in range(30)] + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) + client = CentMLClient(api) + + events = list(client.iter_deployment_logs(123, 2, pod="pod-a", max_lines=10)) + + assert [e.id for e in events] == [e.id for e in all_events] # every line once, in order + # 3 data pages + 1 empty page proving catch-up; a livelock would exceed this. + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 4 + + +def test_iter_deployment_logs_start_time_holds_gray_lines_below_the_window(): + all_events = [ + _log_event("04990-w", 4990), + _log_event("04995-x", 4995), + _log_event("05000-y", 5000), + _log_event("06000-z", 6000), + ] + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) + client = CentMLClient(api) + + events = list(client.iter_deployment_logs(123, 2, pod="pod-a", start_time=5000)) + + # The look-behind lines below start_time are held for dedup but never emitted. + assert [e.id for e in events] == ["05000-y", "06000-z"] + first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] + assert first_call.kwargs["timestamp"] == 4999 # after is exclusive: admits start_time itself + + +def test_iter_deployment_logs_held_state_stays_within_the_dedup_window(): + from centml.sdk.api import LOG_DEDUP_RETENTION_MS + + step_ms = 10_000 + pages = [ + _log_page(*(_log_event(f"{(p * 100 + i) * step_ms:09d}-x", (p * 100 + i) * step_ms) for i in range(100))) + for p in range(1, 50) + ] + [_log_page()] + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + + anchor_sizes = [] + original = CentMLClient.get_deployment_logs + + def spying_get_deployment_logs(self, *args, **kwargs): + if isinstance(kwargs.get("after"), list): + anchor_sizes.append(len(kwargs["after"])) + return original(self, *args, **kwargs) + + with patch.object(CentMLClient, "get_deployment_logs", spying_get_deployment_logs): + events = list(client.iter_deployment_logs(123, 2, pod="pod-a")) + + assert len(events) == 4900 + # Held state is the trimmed dedup window, not the accumulated stream. + assert max(anchor_sizes) <= LOG_DEDUP_RETENTION_MS // step_ms + 1 + + +def test_iter_deployment_logs_merges_pods_by_timestamp_then_id(): + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a", "pod-b"] + ) + + def pages(**kwargs): + if kwargs["timestamp"]: + return _log_page() + if kwargs["pod"] == "pod-a": + return _log_page(_log_event("1-a", 1000), _log_event("3-a", 3000)) + return _log_page(_log_event("2-b", 2000), _log_event("4-b", 4000)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + + events = list(client.iter_deployment_logs(123, 2)) + + assert [(e.id, e.pod) for e in events] == [("1-a", "pod-a"), ("2-b", "pod-b"), ("3-a", "pod-a"), ("4-b", "pod-b")] + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_called_once() + + +def test_iter_deployment_logs_returns_empty_when_no_pod_has_logged(): + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace(pods=[]) + client = CentMLClient(api) + + assert not list(client.iter_deployment_logs(123, 2)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() + + +def test_iter_deployment_logs_follow_polls_at_the_poll_interval(): + api = MagicMock() + responses = iter([_log_page(_log_event("1-a", 1000))]) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = lambda **kwargs: next( + responses, _log_page() + ) + client = CentMLClient(api) + clock = _FakeClock(max_sleeps=3) + monotonic_patch, sleep_patch = _clock_patches(clock) + + with monotonic_patch, sleep_patch: + stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True, poll_interval=2.0) + assert next(stream).id == "1-a" + with pytest.raises(TimeoutError): + next(stream) + + # One request per poll interval once caught up — no hot spinning. + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == clock.sleeps + 1 + + +def test_iter_deployment_logs_follow_delivers_lines_appended_later(): + api = MagicMock() + responses = iter([_log_page(_log_event("1-a", 1000)), _log_page(), _log_page(_log_event("2-b", 2000))]) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = lambda **kwargs: next( + responses, _log_page() + ) + client = CentMLClient(api) + clock = _FakeClock() + monotonic_patch, sleep_patch = _clock_patches(clock) + + with monotonic_patch, sleep_patch: + stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) + assert next(stream).id == "1-a" + assert next(stream).id == "2-b" + + +def test_iter_deployment_logs_follow_picks_up_pods_that_appear_later(): + api = MagicMock() + pod_lists = iter([["pod-a"]]) + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.side_effect = lambda **kwargs: ( + SimpleNamespace(pods=next(pod_lists, ["pod-a", "pod-b"])) + ) + + def pages(**kwargs): + if kwargs["pod"] == "pod-a": + return _log_page(_log_event("1-a", 1000)) if not kwargs["timestamp"] else _log_page() + return _log_page(_log_event("2-b", 2000)) if not kwargs["timestamp"] else _log_page() + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + clock = _FakeClock() + monotonic_patch, sleep_patch = _clock_patches(clock) + + with monotonic_patch, sleep_patch: + stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) + assert next(stream).id == "1-a" + appeared = next(stream) + + assert (appeared.id, appeared.pod) == ("2-b", "pod-b") + assert api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.call_count >= 2 + + +def test_iter_deployment_logs_follow_flushes_past_a_silent_pod(): + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a", "pod-b"] + ) + clock = _FakeClock() + pod_a_pages = iter([_log_page(_log_event("1-a", 1000), _log_event("3-a", 3000))]) + + def pages(**kwargs): + clock.now += 1.0 # requests take wall time; lets the silent-pod hold expire + if kwargs["pod"] == "pod-a": + return next(pod_a_pages, _log_page()) + return _log_page(_log_event("2-b", 2000)) if not kwargs["timestamp"] else _log_page() + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + monotonic_patch, sleep_patch = _clock_patches(clock) + + with monotonic_patch, sleep_patch: + stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) + # pod-b's frontier (2000) gates 3-a at first; once pod-b stays silent past + # the hold, the buffer flushes past it instead of stalling forever. + assert [next(stream).id for _ in range(3)] == ["1-a", "2-b", "3-a"] From 929ed9506fad8b963d86cd6ef52ae45453ef016e Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Tue, 15 Sep 2026 11:00:34 -0400 Subject: [PATCH 02/22] Document iter_deployment_logs in README and logs example Signed-off-by: Honglin Cao --- README.md | 20 ++++++--- examples/sdk/get_deployment_logs.py | 68 +++++++++++++---------------- 2 files changed, 44 insertions(+), 44 deletions(-) diff --git a/README.md b/README.md index 4440529..e5f1882 100644 --- a/README.md +++ b/README.md @@ -55,13 +55,19 @@ delete the deployment automatically. ### Deployment logs SDK example -Logs are read per pod. Discover pod names with `get_deployment_pods()` (terminated -pods still within log retention are included), then read with a -`deployment_log_session()`: `fetch_older()` pages toward the beginning of history and -`fetch_newer()` returns only new lines, while the session keeps the merged, ordered -log in `.events`. `get_deployment_logs_range()` fetches a specific time window -(epoch-millisecond bounds, both optional) and, with `pod=None`, merges every pod's -stream chronologically. The same paging is available statelessly through +`iter_deployment_logs()` streams a revision's logs lazily, oldest first, each line +exactly once, with bounded memory however long the log is — by default merging every +pod chronologically (each event carries its pod name). `follow=False` returns once +caught up; `follow=True` keeps tailing and picks up new pods of the revision as they +first log. `start_time` (epoch ms) bounds the beginning and `pod=` restricts to one +pod — discover names with `get_deployment_pods()` (terminated pods still within log +retention are included). + +For non-streaming access: `get_deployment_logs_range()` fetches a specific time +window as a list (epoch-millisecond bounds, both optional; `pod=None` merges every +pod). A `deployment_log_session()` pages one pod statefully — `fetch_older()` toward +the beginning of history, `fetch_newer()` for only-new lines — keeping the merged, +ordered log in `.events`. The same paging is available statelessly through `get_deployment_logs(before=..., after=...)`, anchored on events you already hold or on a bare epoch-millisecond boundary: diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index 0dd7ec5..fa87e5f 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -1,4 +1,4 @@ -import time +import itertools from datetime import datetime, timezone from centml.sdk.api import get_centml_client @@ -6,55 +6,49 @@ # --- Configuration --- DEPLOYMENT_ID = 1234 # Replace with your deployment ID REVISION_NUMBER = 10 -TAIL_SECONDS = 30 # How long to keep polling for new lines after reading history -TAIL_LINES = 20 # How much history to print before tailing +FOLLOW_LINES = 20 # How many tailed lines to print before stopping the follow def format_event(event) -> str: ts = datetime.fromtimestamp(event.timestamp / 1000, tz=timezone.utc).isoformat() - return f"[{ts}] {event.message}" + return f"[{ts}] {event.pod} {event.message}" def main(): with get_centml_client() as cclient: - # Logs are read per pod: discover the pods that have logged for this revision - # (terminated pods within log retention are included). - pods = cclient.get_deployment_pods(DEPLOYMENT_ID, REVISION_NUMBER) - if not pods: - print("No pods have logged for this revision yet.") - return - - pod = pods[0] - print(f"Reading logs for deployment {DEPLOYMENT_ID} revision {REVISION_NUMBER}, pod {pod}\n") - - # The session tracks what it has fetched and anchors every request itself. - session = cclient.deployment_log_session(DEPLOYMENT_ID, REVISION_NUMBER, pod) - - # Read the full history: newest page first, then page back to the beginning. - while session.fetch_older(): - pass - events = session.events - print(f"Found {len(events)} log entries; showing the last {TAIL_LINES}:\n") - for event in events[-TAIL_LINES:]: + # Stream the revision's full history, all pods merged chronologically. + # The iterator is lazy: pages are fetched as you consume it, and its held + # state stays bounded no matter how many lines stream by. + print(f"Logs for deployment {DEPLOYMENT_ID} revision {REVISION_NUMBER}:\n") + count = 0 + for event in cclient.iter_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER): + print(format_event(event)) + count += 1 + print(f"\nCaught up after {count} lines.") + + # follow=True keeps tailing instead of returning: it re-polls caught-up pods + # every poll_interval seconds and picks up new pods of the revision as they + # first log. Stop by breaking out (or just abandon the iterator). + print(f"\nFollowing; stopping after {FOLLOW_LINES} new lines...") + stream = cclient.iter_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER, follow=True) + for event in itertools.islice(stream, FOLLOW_LINES): print(format_event(event)) - # Keep tailing: each call returns only the lines the session does not hold yet. - print(f"\nPolling for new lines for {TAIL_SECONDS}s...") - deadline = time.monotonic() + TAIL_SECONDS - while time.monotonic() < deadline: - for event in session.fetch_newer(): - print(format_event(event)) - time.sleep(2) - - # The same paging is available statelessly via get_deployment_logs, anchored - # on events you already hold — useful when you manage storage yourself: - # page = cclient.get_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER, pod=pod) # tail - # older = cclient.get_deployment_logs(..., pod=pod, before=page) # empty return = beginning - # newer = cclient.get_deployment_logs(..., pod=pod, after=page) # empty return = nothing new - # A specific time window (all pods merged, oldest first, pod on each event): + # A single pod (discover names with get_deployment_pods) or a bounded start: + # pods = cclient.get_deployment_pods(DEPLOYMENT_ID, REVISION_NUMBER) + # for event in cclient.iter_deployment_logs( + # DEPLOYMENT_ID, REVISION_NUMBER, pod=pods[0], start_time=t1_ms + # ): + # ... + # A specific time window as a list (all pods merged, oldest first): # window = cclient.get_deployment_logs_range( # DEPLOYMENT_ID, REVISION_NUMBER, start_time=t1_ms, end_time=t2_ms # ) + # Manual paging, anchored on events you already hold — useful when you + # manage storage yourself (deployment_log_session wraps this statefully): + # page = cclient.get_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER, pod=pods[0]) # tail + # older = cclient.get_deployment_logs(..., pod=pods[0], before=page) # empty return = beginning + # newer = cclient.get_deployment_logs(..., pod=pods[0], after=page) # empty return = nothing new if __name__ == "__main__": From 3c74db6b7a59ccce928afc00af392aab1abf9c7b Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Tue, 15 Sep 2026 11:24:44 -0400 Subject: [PATCH 03/22] Document migrating deployment log reads from 0.5.x Signed-off-by: Honglin Cao --- README.md | 56 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 56 insertions(+) diff --git a/README.md b/README.md index e5f1882..420fe3e 100644 --- a/README.md +++ b/README.md @@ -75,6 +75,62 @@ or on a bare epoch-millisecond boundary: python examples/sdk/get_deployment_logs.py ``` +### Migrating deployment log reads from 0.5.x + +`get_deployment_logs()` kept its name but not its signature: `start_time`, `end_time`, +`line_count`, `start_from_head` and `stream` are gone, and logs are read per pod. A +0.5.x call raises `TypeError` (or a validation error, if its arguments were positional) +rather than returning something wrong, so no call site fails silently. + +| To | 0.5.x | 0.6.0 | +|---|---|---| +| Read a time window | `get_deployment_logs(id, rev, start_time=, end_time=)` | `get_deployment_logs_range(id, rev, start_time=, end_time=)` | +| Stream a window lazily | the same call with `stream=True` | `iter_deployment_logs(id, rev, start_time=)` | +| Take the newest lines first | `start_from_head=False` | `get_deployment_logs(id, rev, pod)`, then page with `before=` | +| Cap a page | `line_count=n` | `max_lines=n`, at most 5000 | +| Tell which pod a line came from | parse `kubernetes.pod_name` out of `message` | `event.pod` | +| Keep tailing past the window | not supported | `iter_deployment_logs(..., follow=True)` | + +A whole-window read loses its envelope parsing, because `message` is now the log line +itself rather than a JSON record wrapping it: + +```python +# 0.5.x +events = cclient.get_deployment_logs(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2) +for event in events: + record = json.loads(event["message"]) + print(record["kubernetes"]["pod_name"], record["log"]) + +# 0.6.0 +for event in cclient.get_deployment_logs_range(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2): + print(event.pod, event.message) +``` + +A `stream=True` loop becomes an `iter_deployment_logs()` loop, which yields each page as +it arrives just as the old generator did: + +```python +# 0.5.x +for event in cclient.get_deployment_logs( + DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2, stream=True +): + print(json.loads(event["message"])["log"]) + +# 0.6.0 +for event in cclient.iter_deployment_logs(DEPLOYMENT_ID, REVISION, start_time=t1): + print(event.message) +``` + +Two contract changes to check error handling against: a revision that does not exist now +answers 404 where the old endpoint answered 400, and a `max_lines` above 5000 is rejected +before the request leaves the client. + +When paging by hand with `get_deployment_logs(after=...)`, anchor on the events you already +hold rather than on a bare timestamp. Every fetch-newer call re-delivers a short look-behind +span so late-arriving lines are not missed; an events anchor lets the SDK drop the lines you +already have, while a bare-timestamp anchor re-delivers that span undeduplicated and, once +the reader has caught up, stops advancing. `iter_deployment_logs()` handles this for you. + ### Un-installation To uninstall `centml`, simply do: From 3c49222ff6665d1bd50559e3813b0350c759d544 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Tue, 15 Sep 2026 14:10:17 -0400 Subject: [PATCH 04/22] Bound merge memory, pace polling, and split merge delay from dedup Review fixes for iter_deployment_logs: - Per-pod buffers with backpressure (LOG_MERGE_BUFFER_PAGES): a pod far ahead of the merge watermark parks at two pages instead of buffering its whole history against a terminated peer. - Watermark: strict cross-pod order while any pod is catching up; once all are at the tip, hold lines one poll_interval so concurrent pods interleave; single-pod streams release immediately. The dedup window and the merge delay are now separate concerns (LOG_MERGE_HOLD_POLLS is gone), and follow=False drains buffers fully before returning. - Caught-up pods are re-polled at most once per poll_interval (next_poll_at), and a caught-up pod gone from the pod list stops being polled, keeping its dedup window in case it is listed again. - Ordering docs state the contract plainly: late-arriving lines are appended when they arrive (the CloudWatch path dropped them). Signed-off-by: Honglin Cao --- README.md | 7 +- centml/sdk/api.py | 148 ++++++++++++++++-------- tests/test_sdk_api.py | 253 ++++++++++++++++++++++++++++++++++++++---- 3 files changed, 340 insertions(+), 68 deletions(-) diff --git a/README.md b/README.md index 420fe3e..b7d8f22 100644 --- a/README.md +++ b/README.md @@ -61,7 +61,12 @@ pod chronologically (each event carries its pod name). `follow=False` returns on caught up; `follow=True` keeps tailing and picks up new pods of the revision as they first log. `start_time` (epoch ms) bounds the beginning and `pod=` restricts to one pod — discover names with `get_deployment_pods()` (terminated pods still within log -retention are included). +retention are included). Lines are yielded in timestamp order: cross-pod ordering is +strict while catching up on history; at the tip, concurrent pods interleave within +one `poll_interval`, a single-pod tail is released immediately, and a line reaching +the log store later than the server's ~15s re-delivery window is appended when it +arrives rather than inserted in place (the previous CloudWatch-based read path +dropped such lines entirely). For non-streaming access: `get_deployment_logs_range()` fetches a specific time window as a list (epoch-millisecond bounds, both optional; `pod=None` merges every diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 33aa69b..9ec35ae 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -2,7 +2,6 @@ from bisect import insort from contextlib import contextmanager from dataclasses import dataclass, field -from heapq import heappop, heappush from typing import Dict, Iterator, List, Optional, Union import platform_api_python_client @@ -31,11 +30,16 @@ # The server re-delivers a ~15s look-behind window on fetch-newer requests; only the # caller's events within this generous margin of the boundary can be re-delivered. LOG_DEDUP_RETENTION_MS = 300_000 -# In a followed multi-pod merge, a pod that stops logging holds back the merged -# stream at most this many poll intervals before its peers' buffers flush past it. -LOG_MERGE_HOLD_POLLS = 2 +# Merge backpressure: a pod with this many pages buffered ahead of the merge watermark +# is not fetched further until the watermark catches up. Two pages keep the merge fed +# (one page draining while the next waits) yet cap the lookahead, so a pod far ahead +# in time — typically a live pod merged with a terminated predecessor — buffers a +# couple of pages instead of its whole history. +LOG_MERGE_BUFFER_PAGES = 2 # How often a followed multi-pod merge re-lists the revision's pods to pick up -# replacements and scale-ups. +# replacements and scale-ups. Mirrors the server's ~15s fetch-newer look-behind +# horizon: pod discovery lags a new pod's first line by no more than the span the +# server itself re-delivers for late-arriving data. LOG_POD_REFRESH_SECONDS = 15.0 @@ -63,13 +67,17 @@ class DeploymentLogEvent: @dataclass class _PodLogTail: - """Per-pod cursor for iter_deployment_logs: the trimmed dedup window it holds, - the newest timestamp it has fetched (its merge-watermark contribution), and - when it last produced data (monotonic; gates the silent-pod hold).""" + """Per-pod cursor for iter_deployment_logs: the trimmed dedup window it holds (the + anchor), the fetched-but-unreleased events awaiting the merge watermark, the newest + fetched timestamp (its watermark contribution while catching up), whether its last + poll found nothing new, and — once caught up — the earliest monotonic time it may + be polled again.""" - last_data: float held: List[DeploymentLogEvent] = field(default_factory=list) + buffer: List[DeploymentLogEvent] = field(default_factory=list) frontier: int = -1 + caught_up: bool = False + next_poll_at: float = 0.0 class CentMLClient: @@ -366,46 +374,63 @@ def iter_deployment_logs( ) -> Iterator[DeploymentLogEvent]: """Stream a revision's logs lazily, oldest first, each line exactly once, each event carrying its pod name. Pages are fetched as the iterator is - consumed, and the state held per pod is trimmed to the server's - re-delivery window, so memory stays bounded however many lines stream by. - - pod=None merges every pod of the revision into one stream ordered by - (timestamp, id); pods are buffered and emitted up to the merge watermark - (the oldest frontier any pod has fetched to). start_time (epoch ms, - inclusive) bounds the beginning; None reads from the start of the log - window. follow=False returns once every pod is caught up. follow=True - keeps tailing: caught-up pods are re-polled every poll_interval seconds - and the revision's pod list is re-read every LOG_POD_REFRESH_SECONDS so - replacement pods join the merge as they first log. While following, a - pod silent for LOG_MERGE_HOLD_POLLS poll intervals stops gating the - watermark, so cross-pod ordering is best-effort beyond that bound; a - single-pod stream is always strictly ordered. + consumed; per pod, the dedup window is trimmed to the server's re-delivery + span and at most LOG_MERGE_BUFFER_PAGES pages sit buffered ahead of the + merge, so memory stays bounded however many lines stream by. + + pod=None merges every pod of the revision into one (timestamp, id)-ordered + stream. Cross-pod ordering is strict while any pod is still catching up on + history; once every pod is at the tip, a fetched line is held for at most + one poll_interval so concurrent pods interleave, and a single-pod stream + releases immediately. Lines are yielded in timestamp order; a line that + reaches the log store later than the server's ~15s re-delivery window is + appended when it arrives rather than inserted in place (the previous + CloudWatch-based read path dropped such lines entirely). + + start_time (epoch ms, inclusive) bounds the beginning; None reads from the + start of the log window. follow=False returns once every pod is caught up, + draining the merge buffers fully. follow=True keeps tailing: each + caught-up pod is re-polled at most once per poll_interval, the pod list is + re-read every LOG_POD_REFRESH_SECONDS so replacement pods join the merge + as they first log, and a caught-up pod that has left the pod list is + dropped from polling (its dedup window is kept in case it is listed + again). """ initial_boundary = start_time - 1 if start_time else 0 - now = time.monotonic() - last_refresh = now - pods = [pod] if pod is not None else self.get_deployment_pods(deployment_id, revision_number) - tails: Dict[str, _PodLogTail] = {name: _PodLogTail(last_data=now) for name in pods} - pending: list = [] # min-heap of (timestamp, id, event) awaiting the watermark + buffer_limit = LOG_MERGE_BUFFER_PAGES * max_lines + merge_delay_ms = int(poll_interval * 1000) + last_refresh = time.monotonic() + listed = [pod] if pod is not None else self.get_deployment_pods(deployment_id, revision_number) + tails: Dict[str, _PodLogTail] = {name: _PodLogTail() for name in listed} + retired: Dict[str, _PodLogTail] = {} while True: if follow and pod is None and time.monotonic() - last_refresh >= LOG_POD_REFRESH_SECONDS: last_refresh = time.monotonic() - for name in self.get_deployment_pods(deployment_id, revision_number): + listed = self.get_deployment_pods(deployment_id, revision_number) + for name in listed: if name not in tails: - tails[name] = _PodLogTail(last_data=last_refresh) + # a retired pod that reappears resumes from its own dedup window, + # so nothing it already delivered is re-yielded + tails[name] = retired.pop(name, _PodLogTail()) - fetched_any = False for name, tail in list(tails.items()): + if len(tail.buffer) >= buffer_limit: + continue # backpressure: let the merge watermark catch up before fetching more + if tail.caught_up and (not follow or time.monotonic() < tail.next_poll_at): + continue page = self.get_deployment_logs( deployment_id, revision_number, name, after=tail.held or initial_boundary, max_lines=max_lines ) if not page: - if not follow: - del tails[name] # caught up: stop gating the watermark on it + tail.caught_up = True + tail.next_poll_at = time.monotonic() + poll_interval + if follow and pod is None and name not in listed and not tail.buffer: + # gone from the pod list and caught up: stop polling it — it was + # not gating the watermark, so nothing waits on its removal + retired[name] = tails.pop(name) continue - fetched_any = True - tail.last_data = time.monotonic() + tail.caught_up = False for raw in page: event = DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=name) if tail.held and event.id <= tail.held[-1].id: @@ -417,24 +442,55 @@ def iter_deployment_logs( # Anchoring at start_time - 1 re-delivers the look-behind span below # start_time; those ids must be held for dedup but never emitted. if start_time is None or event.timestamp >= start_time: - heappush(pending, (event.timestamp, event.id, event)) + if tail.buffer and event.id <= tail.buffer[-1].id: + insort(tail.buffer, event, key=lambda buffered_event: buffered_event.id) + else: + tail.buffer.append(event) tail.held = _recent_anchor(tail.held) tail.frontier = tail.held[-1].timestamp - if follow: - hold_cap = LOG_MERGE_HOLD_POLLS * poll_interval - gating = [t.frontier for t in tails.values() if time.monotonic() - t.last_data <= hold_cap] + # The dedup window (~15s of server re-delivery) and the merge delay are two + # different concerns: the former decides what `held` keeps for the anchor, + # the latter only how long a fetched line waits so concurrent pods interleave. + lagging = [tail.frontier for tail in tails.values() if not tail.caught_up] + if lagging: + watermark = min(lagging) # catching up: strict cross-pod order + elif not follow or len(tails) <= 1: + # every pod caught up with nothing to merge against: release everything — + # follow=False must drain fully before returning, and a single-pod tail + # must not invent latency the old single-stream reader never had + watermark = None else: - gating = [t.frontier for t in tails.values()] - watermark = min(gating) if gating else None - while pending and (watermark is None or pending[0][0] <= watermark): - yield heappop(pending)[2] + # steady-state multi-pod tail: hold a line just long enough for the + # peers' pages to arrive. Client wall clock against server timestamps: + # skew only shifts this interleave window, never drops a line. + watermark = int(time.time() * 1000) - merge_delay_ms + ready: List[DeploymentLogEvent] = [] + for tail in tails.values(): + cut = 0 + while cut < len(tail.buffer) and (watermark is None or tail.buffer[cut].timestamp <= watermark): + cut += 1 + if cut: + ready += tail.buffer[:cut] + del tail.buffer[:cut] + ready.sort(key=lambda event: (event.timestamp, event.id)) + yield from ready if not follow: - if not tails: + if all(tail.caught_up for tail in tails.values()): return - elif not fetched_any: - time.sleep(poll_interval) + continue + now = time.monotonic() + if any( + len(tail.buffer) < buffer_limit and (not tail.caught_up or now >= tail.next_poll_at) + for tail in tails.values() + ): + continue # something is fetchable right now + next_wake = min( + (tail.next_poll_at for tail in tails.values() if len(tail.buffer) < buffer_limit), + default=now + poll_interval, + ) + time.sleep(max(0.0, min(next_wake - now, poll_interval))) def deployment_log_session( self, deployment_id: int, revision_number: int, pod: str, events: Optional[list] = None diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index c4434c4..e02e0bd 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -1,3 +1,5 @@ +import time +from contextlib import contextmanager from types import SimpleNamespace from unittest.mock import MagicMock, patch @@ -13,7 +15,7 @@ ) from centml.sdk import ApiException -from centml.sdk.api import CentMLClient, get_centml_client +from centml.sdk.api import LOG_DEDUP_RETENTION_MS, LOG_MERGE_BUFFER_PAGES, CentMLClient, get_centml_client from centml.sdk.config import settings @@ -636,7 +638,9 @@ def test_log_session_long_window_keeps_boundary_and_dedup_correct(): class _FakeClock: - """Deterministic stand-in for time.monotonic/time.sleep in follow-mode tests.""" + """Deterministic stand-in for time.monotonic/time.time/time.sleep in follow-mode tests.""" + + EPOCH = 1_700_000_000.0 # wall-clock base at epoch scale, for the merge-delay watermark def __init__(self, max_sleeps=100): self.now = 0.0 @@ -646,6 +650,12 @@ def __init__(self, max_sleeps=100): def monotonic(self): return self.now + def time(self): + return self.EPOCH + self.now + + def wall_ms(self): + return int(self.time() * 1000) + def sleep(self, seconds): self.sleeps += 1 if self.sleeps > self._max_sleeps: @@ -653,8 +663,14 @@ def sleep(self, seconds): self.now += seconds -def _clock_patches(clock): - return (patch("centml.sdk.api.time.monotonic", clock.monotonic), patch("centml.sdk.api.time.sleep", clock.sleep)) +@contextmanager +def _patched_clock(clock): + with ( + patch("centml.sdk.api.time.monotonic", clock.monotonic), + patch("centml.sdk.api.time.time", clock.time), + patch("centml.sdk.api.time.sleep", clock.sleep), + ): + yield clock def test_iter_deployment_logs_yields_first_page_before_fetching_the_next(): @@ -745,8 +761,6 @@ def test_iter_deployment_logs_start_time_holds_gray_lines_below_the_window(): def test_iter_deployment_logs_held_state_stays_within_the_dedup_window(): - from centml.sdk.api import LOG_DEDUP_RETENTION_MS - step_ms = 10_000 pages = [ _log_page(*(_log_event(f"{(p * 100 + i) * step_ms:09d}-x", (p * 100 + i) * step_ms) for i in range(100))) @@ -812,9 +826,8 @@ def test_iter_deployment_logs_follow_polls_at_the_poll_interval(): ) client = CentMLClient(api) clock = _FakeClock(max_sleeps=3) - monotonic_patch, sleep_patch = _clock_patches(clock) - with monotonic_patch, sleep_patch: + with _patched_clock(clock): stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True, poll_interval=2.0) assert next(stream).id == "1-a" with pytest.raises(TimeoutError): @@ -832,9 +845,8 @@ def test_iter_deployment_logs_follow_delivers_lines_appended_later(): ) client = CentMLClient(api) clock = _FakeClock() - monotonic_patch, sleep_patch = _clock_patches(clock) - with monotonic_patch, sleep_patch: + with _patched_clock(clock): stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) assert next(stream).id == "1-a" assert next(stream).id == "2-b" @@ -855,9 +867,8 @@ def pages(**kwargs): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages client = CentMLClient(api) clock = _FakeClock() - monotonic_patch, sleep_patch = _clock_patches(clock) - with monotonic_patch, sleep_patch: + with _patched_clock(clock): stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) assert next(stream).id == "1-a" appeared = next(stream) @@ -866,26 +877,226 @@ def pages(**kwargs): assert api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.call_count >= 2 -def test_iter_deployment_logs_follow_flushes_past_a_silent_pod(): +def test_iter_deployment_logs_follow_does_not_gate_on_a_caught_up_silent_pod(): api = MagicMock() api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( pods=["pod-a", "pod-b"] ) - clock = _FakeClock() - pod_a_pages = iter([_log_page(_log_event("1-a", 1000), _log_event("3-a", 3000))]) + pod_a_pages = iter( + [_log_page(_log_event("1-a", 1000), _log_event("3-a", 3000)), _log_page(_log_event("4-a", 4000))] + ) def pages(**kwargs): - clock.now += 1.0 # requests take wall time; lets the silent-pod hold expire if kwargs["pod"] == "pod-a": return next(pod_a_pages, _log_page()) return _log_page(_log_event("2-b", 2000)) if not kwargs["timestamp"] else _log_page() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages client = CentMLClient(api) - monotonic_patch, sleep_patch = _clock_patches(clock) + clock = _FakeClock() + + with _patched_clock(clock): + stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) + # Round one: pod-b's frontier (2000) gates 3-a. After pod-b polls empty it is + # caught up and stops gating, so pod-a's lines flow without any hold window. + assert [next(stream).id for _ in range(4)] == ["1-a", "2-b", "3-a", "4-a"] + + +def test_iter_deployment_logs_backpressures_a_pod_far_ahead_of_the_watermark(): + # A terminated old pod gates the watermark while a live pod's history is far newer; + # without backpressure every old-pod round would buffer another new-pod page, growing + # the merge buffer with the live pod's whole history. + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-old", "pod-new"] + ) + events = { + "pod-old": [_log_event(f"old-{i:04d}", 1000 + i) for i in range(100)], + "pod-new": [_log_event(f"new-{i:04d}", 10_000_000 + i) for i in range(100)], + } + + def pages(**kwargs): + newer = [e for e in events[kwargs["pod"]] if e.timestamp > (kwargs["timestamp"] or 0)] + return _log_page(*newer[: kwargs["max_lines"]]) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + + calls = {"pod-old": 0, "pod-new": 0} + new_calls_while_old_active = [] + original = CentMLClient.get_deployment_logs + + def spying_get_deployment_logs(self, *args, **kwargs): + calls[args[2]] += 1 + if args[2] == "pod-old": + new_calls_while_old_active.append(calls["pod-new"]) + return original(self, *args, **kwargs) + + with patch.object(CentMLClient, "get_deployment_logs", spying_get_deployment_logs): + yielded = list(client.iter_deployment_logs(123, 2, max_lines=10)) + + assert [e.id for e in yielded] == [e.id for e in events["pod-old"]] + [e.id for e in events["pod-new"]] + # While the old pod was still draining, the new pod was fetched at most its buffer + # cap (LOG_MERGE_BUFFER_PAGES pages), not once per round. + assert max(new_calls_while_old_active) <= LOG_MERGE_BUFFER_PAGES + assert calls["pod-new"] == 11 # 10 data pages + 1 empty page, none wasted on re-polls + + +def test_iter_deployment_logs_follow_single_pod_appends_late_arrivals(): + # A line that reaches the log store late is re-delivered with a fresh id and yields + # after newer lines — visible late delivery, where the CloudWatch path dropped it. + api = MagicMock() + responses = iter( + [ + _log_page(*(_log_event(f"{1000 + i}-x", 1000 + i) for i in range(5))), + _log_page(_log_event("1002-late", 1002), _log_event("2000-f", 2000)), + ] + ) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = lambda **kwargs: next( + responses, _log_page() + ) + client = CentMLClient(api) + clock = _FakeClock() + + with _patched_clock(clock): + stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) + got = [next(stream).id for _ in range(7)] + + assert got == ["1000-x", "1001-x", "1002-x", "1003-x", "1004-x", "1002-late", "2000-f"] + + +def test_iter_deployment_logs_drains_lines_newer_than_the_merge_delay_on_return(): + # follow=False must drain the merge buffers unconditionally once every pod is caught + # up; lines newer than any time-based watermark must not be silently dropped. + recent_ms = int(time.time() * 1000) + 60_000 + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a", "pod-b"] + ) + + def pages(**kwargs): + if kwargs["timestamp"]: + return _log_page() + if kwargs["pod"] == "pod-a": + return _log_page(_log_event("1000-a", 1000), _log_event(f"{recent_ms}-a", recent_ms)) + return _log_page(_log_event("500-b", 500)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + + events = list(client.iter_deployment_logs(123, 2)) + + assert [e.id for e in events] == ["500-b", "1000-a", f"{recent_ms}-a"] + + +def test_iter_deployment_logs_follow_retires_pods_gone_from_the_pod_list(): + api = MagicMock() + pod_lists = iter([["pod-a", "pod-b"]]) + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.side_effect = lambda **kwargs: ( + SimpleNamespace(pods=next(pod_lists, ["pod-a"])) + ) + clock = _FakeClock() + calls = {"pod-a": 0, "pod-b": 0} + pod_b_pages = iter([_log_page(_log_event("500-b", 500))]) + + def pages(**kwargs): + clock.now += 0.5 # requests take wall time, letting poll pacing and refresh advance + calls[kwargs["pod"]] += 1 + if kwargs["pod"] == "pod-b": + return next(pod_b_pages, _log_page()) + step = calls["pod-a"] + return _log_page(_log_event(f"{10_000 + step}-a", 10_000 + step)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) - with monotonic_patch, sleep_patch: + with _patched_clock(clock): stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) - # pod-b's frontier (2000) gates 3-a at first; once pod-b stays silent past - # the hold, the buffer flushes past it instead of stalling forever. - assert [next(stream).id for _ in range(3)] == ["1-a", "2-b", "3-a"] + first_batch = [next(stream) for _ in range(40)] + calls_b_after_retirement = calls["pod-b"] + second_batch = [next(stream) for _ in range(30)] + + # pod-b left the pod list at the first refresh and was caught up: polling it stopped. + assert calls["pod-b"] == calls_b_after_retirement + # Its one line was delivered exactly once, and nothing else was lost or duplicated. + ids = [e.id for e in first_batch + second_batch] + assert ids.count("500-b") == 1 and len(set(ids)) == len(ids) + + +def test_iter_deployment_logs_follow_holds_steady_state_lines_for_the_merge_delay(): + # Multi-pod steady state: a residual line above a peer's frontier is released once + # the merge delay (one poll_interval) has passed, not held indefinitely and not + # released before its peers had a chance to interleave. + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a", "pod-b"] + ) + clock = _FakeClock() + fresh_ms = clock.wall_ms() - 10 + fetch_time = {} + + def pages(**kwargs): + if kwargs["timestamp"]: + return _log_page() + if kwargs["pod"] == "pod-a": + fetch_time["fresh"] = clock.now + return _log_page(_log_event(f"{fresh_ms - 5000}-a", fresh_ms - 5000), _log_event(f"{fresh_ms}-a", fresh_ms)) + return _log_page(_log_event(f"{fresh_ms - 6000}-b", fresh_ms - 6000)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + + with _patched_clock(clock): + stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) + assert next(stream).id == f"{fresh_ms - 6000}-b" + assert next(stream).id == f"{fresh_ms - 5000}-a" + released = next(stream) + + assert released.id == f"{fresh_ms}-a" + assert clock.now - fetch_time["fresh"] >= 2.0 # held for the merge delay, then released + + +def test_iter_deployment_logs_follow_single_pod_releases_without_merge_delay(): + api = MagicMock() + clock = _FakeClock() + fresh_ms = clock.wall_ms() - 10 + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event(f"{fresh_ms}-a", fresh_ms)) + ] + client = CentMLClient(api) + + with _patched_clock(clock): + stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) + assert next(stream).id == f"{fresh_ms}-a" + + assert clock.sleeps == 0 # released in its own fetch round: no invented tail latency + + +def test_iter_deployment_logs_follow_paces_caught_up_pods_while_a_peer_streams(): + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a", "pod-b"] + ) + clock = _FakeClock() + calls = {"pod-a": 0, "pod-b": 0} + + def pages(**kwargs): + clock.now += 0.5 # requests take wall time + calls[kwargs["pod"]] += 1 + if kwargs["pod"] == "pod-b": + return _log_page() # permanently idle + step = calls["pod-a"] + return _log_page(_log_event(f"{10_000 + step}-a", 10_000 + step)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + client = CentMLClient(api) + + with _patched_clock(clock): + stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) + for _ in range(20): + next(stream) + + # The idle pod is re-polled at most once per poll_interval of elapsed time, not once + # per round of its streaming peer. + assert calls["pod-b"] <= clock.now / 2.0 + 2 + assert calls["pod-b"] < calls["pod-a"] / 2 From e2ab29adf63007bbee147e95bee1ffa8c28bf90a Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Tue, 15 Sep 2026 14:47:07 -0400 Subject: [PATCH 05/22] Qualify the whole-millisecond page guarantee A millisecond holding more than the log store's per-query ceiling cannot be delivered whole; the page carries the 5000 nearest its paging direction. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 9ec35ae..f20d1fe 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -282,7 +282,10 @@ def get_deployment_logs( boundary itself — after=0 scans from the head of the log window; an int after anchor holds no event ids, so the re-delivered span at the boundary comes through undeduplicated. An empty anchor list raises ValueError. Pages never - split a millisecond, so a delivered boundary millisecond is always complete. + split a millisecond, so a delivered boundary millisecond is complete unless it + holds more than the log store's 5000-line per-query ceiling — past that the page + carries the 5000 nearest its direction (the newest when paging older, the oldest + when paging newer), independently of max_lines. """ if before is not None and after is not None: raise ValueError("before and after are mutually exclusive") From cdd590bdfafad555f1e84b79839c5b5d20ff2eb8 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Tue, 15 Sep 2026 14:57:50 -0400 Subject: [PATCH 06/22] State the follow ordering bound as the merge delay The ordering bound is the release point (one poll_interval merging pods, immediate for a single pod), not the server's re-delivery window, which bounds delivery instead. Signed-off-by: Honglin Cao --- README.md | 8 +++++--- centml/sdk/api.py | 10 ++++++---- 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index b7d8f22..92388a7 100644 --- a/README.md +++ b/README.md @@ -64,9 +64,11 @@ pod — discover names with `get_deployment_pods()` (terminated pods still withi retention are included). Lines are yielded in timestamp order: cross-pod ordering is strict while catching up on history; at the tip, concurrent pods interleave within one `poll_interval`, a single-pod tail is released immediately, and a line reaching -the log store later than the server's ~15s re-delivery window is appended when it -arrives rather than inserted in place (the previous CloudWatch-based read path -dropped such lines entirely). +the log store after its timestamp has passed that release point is appended rather +than inserted — so a single-pod follow appends any late line and a multi-pod follow +keeps order for lines under one `poll_interval` late. Such lines are still delivered +exactly once, within the server's ~15s re-delivery window; the previous +CloudWatch-based read path dropped them entirely. For non-streaming access: `get_deployment_logs_range()` fetches a specific time window as a list (epoch-millisecond bounds, both optional; `pod=None` merges every diff --git a/centml/sdk/api.py b/centml/sdk/api.py index f20d1fe..4e28719 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -385,10 +385,12 @@ def iter_deployment_logs( stream. Cross-pod ordering is strict while any pod is still catching up on history; once every pod is at the tip, a fetched line is held for at most one poll_interval so concurrent pods interleave, and a single-pod stream - releases immediately. Lines are yielded in timestamp order; a line that - reaches the log store later than the server's ~15s re-delivery window is - appended when it arrives rather than inserted in place (the previous - CloudWatch-based read path dropped such lines entirely). + releases immediately. Lines are yielded in timestamp order, except that one + reaching the log store after its timestamp has passed that release point is + appended rather than inserted: a single-pod follow appends any late line, a + multi-pod follow keeps order for lines under one poll_interval late. They are + still delivered exactly once, within the server's ~15s re-delivery window — + the previous CloudWatch-based read path dropped such lines entirely. start_time (epoch ms, inclusive) bounds the beginning; None reads from the start of the log window. follow=False returns once every pod is caught up, From 75655e39515667645ca244bb4a92458cb630190d Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 09:10:14 -0400 Subject: [PATCH 07/22] Consolidate deployment log fetching into a single fetch_logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replace the iter_deployment_logs generator with fetch_logs, one reader for every deployment-log shape: an inclusive [start_time, end_time] window (either bound optional and pure), a newest_first flag selecting only the order chunks arrive, lazy chunks of 1..chunk_size events, and pod=None merging every pod of the revision into one stream. fetch_logs validates eagerly and returns a private generator, so a bad call raises at the call site rather than at the first next(). Forward reads keep the dedup-anchored page walk (the server re-delivers a ~15s look-behind span); backward reads page with bare exclusive int boundaries — pages never split a millisecond — and need no dedup state. The cross-pod merge is direction-aware: forward releases lines at or below the minimum newest-buffered frontier, backward mirrors it with the maximum oldest-buffered frontier, and LOG_MERGE_BUFFER_PAGES backpressure bounds memory in both directions. Lines inside every chunk stay in ascending (timestamp, id) order regardless of direction. get_deployment_logs, get_deployment_logs_range and deployment_log_session delegate to the shared _fetch_log_page primitive and warn as deprecated; no SDK-internal path trips its own warning. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 406 +++++++++++++++++--------- tests/pytest.ini | 1 + tests/test_sdk_api.py | 663 +++++++++++++++++++++++++----------------- 3 files changed, 665 insertions(+), 405 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 4e28719..eafbf76 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -1,4 +1,4 @@ -import time +import warnings from bisect import insort from contextlib import contextmanager from dataclasses import dataclass, field @@ -36,11 +36,6 @@ # in time — typically a live pod merged with a terminated predecessor — buffers a # couple of pages instead of its whole history. LOG_MERGE_BUFFER_PAGES = 2 -# How often a followed multi-pod merge re-lists the revision's pods to pick up -# replacements and scale-ups. Mirrors the server's ~15s fetch-newer look-behind -# horizon: pod discovery lags a new pod's first line by no more than the span the -# server itself re-delivers for late-arriving data. -LOG_POD_REFRESH_SECONDS = 15.0 def _recent_anchor(events: list) -> list: @@ -66,18 +61,16 @@ class DeploymentLogEvent: @dataclass -class _PodLogTail: - """Per-pod cursor for iter_deployment_logs: the trimmed dedup window it holds (the - anchor), the fetched-but-unreleased events awaiting the merge watermark, the newest - fetched timestamp (its watermark contribution while catching up), whether its last - poll found nothing new, and — once caught up — the earliest monotonic time it may - be polled again.""" - - held: List[DeploymentLogEvent] = field(default_factory=list) +class _PodLogStream: + """Per-pod merge state for fetch_logs: the pod's page iterator, its fetched-but- + unreleased events awaiting the merge watermark, its watermark contribution (the + newest buffered timestamp reading forward, the oldest reading backward), and + whether the iterator has finished its window.""" + + pages: Iterator[List[DeploymentLogEvent]] buffer: List[DeploymentLogEvent] = field(default_factory=list) frontier: int = -1 - caught_up: bool = False - next_poll_at: float = 0.0 + exhausted: bool = False class CentMLClient: @@ -266,7 +259,9 @@ def get_deployment_logs( after: Optional[Union[list, int]] = None, max_lines: int = DEFAULT_LOG_PAGE_LINES, ) -> list: - """Fetch one page of a pod's logs, oldest-first. Use get_deployment_pods() to + """Deprecated: use fetch_logs() instead. + + Fetch one page of a pod's logs, oldest-first. Use get_deployment_pods() to discover pod names and get_deployment_revisions() for the revision number. before and after anchor the page to events a previous call returned for the @@ -287,6 +282,23 @@ def get_deployment_logs( carries the 5000 nearest its direction (the newest when paging older, the oldest when paging newer), independently of max_lines. """ + warnings.warn("get_deployment_logs() is deprecated; use fetch_logs() instead", DeprecationWarning, stacklevel=2) + return self._fetch_log_page( + deployment_id, revision_number, pod, before=before, after=after, max_lines=max_lines + ) + + # pylint: disable=R0917 + def _fetch_log_page( + self, + deployment_id: int, + revision_number: int, + pod: str, + before: Optional[Union[list, int]] = None, + after: Optional[Union[list, int]] = None, + max_lines: int = DEFAULT_LOG_PAGE_LINES, + ) -> list: + """The page primitive behind fetch_logs and the deprecated readers — the + contract get_deployment_logs() documents, without the deprecation warning.""" if before is not None and after is not None: raise ValueError("before and after are mutually exclusive") @@ -332,10 +344,15 @@ def get_deployment_logs_range( start_time: Optional[int] = None, end_time: Optional[int] = None, ) -> List[DeploymentLogEvent]: - """Fetch every log line in [start_time, end_time] (epoch ms, inclusive; both + """Deprecated: use fetch_logs() instead. + + Fetch every log line in [start_time, end_time] (epoch ms, inclusive; both optional — an open end reads to the beginning or the present), oldest first. pod=None reads all pods of the revision and merges the streams chronologically; each returned event carries its pod name.""" + warnings.warn( + "get_deployment_logs_range() is deprecated; use fetch_logs() instead", DeprecationWarning, stacklevel=2 + ) if start_time is not None and end_time is not None and start_time > end_time: raise ValueError("start_time must not exceed end_time") @@ -347,7 +364,7 @@ def get_deployment_logs_range( # after is exclusive, so start_time - 1 admits lines at start_time itself; # start_time 0 (or None) means the whole window — scan from the head. anchor: Union[list, int] = _recent_anchor(events) if events else (start_time - 1 if start_time else 0) - page = self.get_deployment_logs( + page = self._fetch_log_page( deployment_id, revision_number, pod_name, after=anchor, max_lines=MAX_LOG_PAGE_LINES ) if not page: @@ -364,151 +381,253 @@ def get_deployment_logs_range( merged.sort(key=lambda event: event.id) return merged + def _iter_pod_log_pages( + self, deployment_id: int, revision_number: int, pod: str, start_ms: int, end_time: Optional[int] + ) -> Iterator[List[DeploymentLogEvent]]: + """Page one pod's logs within [start_ms, end_time] oldest first, yielding each + non-empty in-window page once. The held dedup anchor is trimmed to the server's + re-delivery span, so state never grows with the stream.""" + held: list = [] + # after is exclusive, so start_ms - 1 admits lines at start_ms itself; + # start_ms 0 means the whole log window — scan from the head. + initial_boundary = max(start_ms - 1, 0) + while True: + anchor: Union[list, int] = _recent_anchor(held) if held else initial_boundary + page = self._fetch_log_page(deployment_id, revision_number, pod, after=anchor, max_lines=MAX_LOG_PAGE_LINES) + if not page: + return + emitted: List[DeploymentLogEvent] = [] + past_end = False + for raw in page: + if held and raw.id <= held[-1].id: + # Late arrival inside the look-behind span: keep the held window + # id-ordered (id order == time order) so trimming stays correct. + insort(held, raw, key=lambda held_event: held_event.id) + else: + held.append(raw) + # Anchoring at start_ms - 1 re-delivers the look-behind span below + # start_ms; those ids must be held for dedup but never emitted. + if raw.timestamp < start_ms: + continue + if end_time is not None and raw.timestamp > end_time: + past_end = True + continue + emitted.append(DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod)) + held = _recent_anchor(held) + if emitted: + yield emitted + if past_end: + return + + def _iter_pod_log_pages_backward( + self, deployment_id: int, revision_number: int, pod: str, start_time: Optional[int], end_time: Optional[int] + ) -> Iterator[List[DeploymentLogEvent]]: + """Page one pod's logs within [start_time, end_time] newest page first, each + page internally oldest-first. A backward walk visits each time region once + and before pages carry no re-delivery span, so no dedup state is needed.""" + # before is exclusive, so end_time + 1 admits lines at end_time itself; no + # end_time means no boundary — the server answers with the tail page. + boundary: Optional[int] = None if end_time is None else end_time + 1 + while True: + page = self._fetch_log_page( + deployment_id, revision_number, pod, before=boundary, max_lines=MAX_LOG_PAGE_LINES + ) + if not page: + return + emitted = [ + DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod) + for raw in page + if start_time is None or raw.timestamp >= start_time + ] + if emitted: + yield emitted + if start_time is not None and page[0].timestamp < start_time: + return + # Pages never split a millisecond, so an exclusive boundary at the oldest + # delivered timestamp neither re-delivers nor skips. + boundary = page[0].timestamp + # pylint: disable=R0917 - def iter_deployment_logs( + def fetch_logs( self, deployment_id: int, revision_number: int, pod: Optional[str] = None, start_time: Optional[int] = None, - follow: bool = False, - poll_interval: float = 2.0, - max_lines: int = MAX_LOG_PAGE_LINES, - ) -> Iterator[DeploymentLogEvent]: - """Stream a revision's logs lazily, oldest first, each line exactly once, - each event carrying its pod name. Pages are fetched as the iterator is - consumed; per pod, the dedup window is trimmed to the server's re-delivery - span and at most LOG_MERGE_BUFFER_PAGES pages sit buffered ahead of the - merge, so memory stays bounded however many lines stream by. - - pod=None merges every pod of the revision into one (timestamp, id)-ordered - stream. Cross-pod ordering is strict while any pod is still catching up on - history; once every pod is at the tip, a fetched line is held for at most - one poll_interval so concurrent pods interleave, and a single-pod stream - releases immediately. Lines are yielded in timestamp order, except that one - reaching the log store after its timestamp has passed that release point is - appended rather than inserted: a single-pod follow appends any late line, a - multi-pod follow keeps order for lines under one poll_interval late. They are - still delivered exactly once, within the server's ~15s re-delivery window — - the previous CloudWatch-based read path dropped such lines entirely. - - start_time (epoch ms, inclusive) bounds the beginning; None reads from the - start of the log window. follow=False returns once every pod is caught up, - draining the merge buffers fully. follow=True keeps tailing: each - caught-up pod is re-polled at most once per poll_interval, the pod list is - re-read every LOG_POD_REFRESH_SECONDS so replacement pods join the merge - as they first log, and a caught-up pod that has left the pod list is - dropped from polling (its dedup window is kept in case it is listed - again). + end_time: Optional[int] = None, + newest_first: bool = False, + chunk_size: int = DEFAULT_LOG_PAGE_LINES, + ) -> Iterator[List[DeploymentLogEvent]]: + """Fetch a revision's stored log lines within [start_time, end_time] (epoch + ms, inclusive; omit either bound to leave that side unbounded), yielded + lazily as chunks of 1..chunk_size DeploymentLogEvent — every chunk except + possibly the last holds exactly chunk_size — each stored line at most once, + each event carrying its pod name. + + newest_first selects only the order chunks arrive: False (the default) + walks the window oldest chunk first, True newest chunk first. Lines inside + every chunk are always in ascending (timestamp, id) order regardless of + direction. The defaults read the full retained history to the present; + newest_first=True with no bounds tails backward from the newest stored + line; start_time alone catches up from a known point to the present. + + Exhaustion is the only termination signal: the iterator ends once the + window is delivered, and one that yields nothing means the window holds no + stored lines (aged out of retention, before the deployment existed, an + unknown or not-yet-logging pod, or genuinely empty). There is no follow + mode; tailing is a caller loop of forward fetch_logs calls with + overlapping windows, deduplicated by event.id across calls (the README + documents a memory-bounded recipe — cross-call dedup is the caller's job). + + pod=None merges every pod of the revision into one stream; pass a name + from get_deployment_pods() to read a single pod. Nothing is fetched before + the first next(), and memory stays bounded however large the window: per + pod, at most LOG_MERGE_BUFFER_PAGES fetched pages wait in the merge and + the forward dedup anchor is trimmed to the server's re-delivery span. + + Ordering caveats. Forward: a line the log store received late (within its + ~15s re-delivery span) lands in a later chunk than its timestamp position — + never duplicated, but out of order across chunks; sort by event.id where + strict order matters. Backward: each time region is visited once, so a + line arriving late for a region already passed is absent from that call — + everything older than roughly the read's start minus the ingest lag is + complete; when completeness of the newest lines matters, read forward. + A single millisecond holding more than 5000 lines cannot be delivered + whole: a page carries the 5000 nearest its paging direction, so a forward + read retrieves at most 10000 of it and the middle is unreachable. """ - initial_boundary = start_time - 1 if start_time else 0 - buffer_limit = LOG_MERGE_BUFFER_PAGES * max_lines - merge_delay_ms = int(poll_interval * 1000) - last_refresh = time.monotonic() - listed = [pod] if pod is not None else self.get_deployment_pods(deployment_id, revision_number) - tails: Dict[str, _PodLogTail] = {name: _PodLogTail() for name in listed} - retired: Dict[str, _PodLogTail] = {} + if chunk_size < 1: + raise ValueError("chunk_size must be a positive number of lines") + if (start_time is not None and start_time < 0) or (end_time is not None and end_time < 0): + raise ValueError("start_time and end_time are epoch milliseconds and must not be negative") + if start_time is not None and end_time is not None and start_time > end_time: + raise ValueError("start_time must not exceed end_time") + return self._iter_log_chunks( + deployment_id, revision_number, pod, start_time, end_time, newest_first, chunk_size + ) + # pylint: disable=R0917 + def _iter_log_chunks( + self, + deployment_id: int, + revision_number: int, + pod: Optional[str], + start_time: Optional[int], + end_time: Optional[int], + newest_first: bool, + chunk_size: int, + ) -> Iterator[List[DeploymentLogEvent]]: + """The generator behind fetch_logs, split out so fetch_logs raises its + ValueErrors at the call site rather than at the first next().""" + + def pod_pages(name: str) -> Iterator[List[DeploymentLogEvent]]: + if newest_first: + return self._iter_pod_log_pages_backward(deployment_id, revision_number, name, start_time, end_time) + return self._iter_pod_log_pages( + deployment_id, revision_number, name, start_time if start_time is not None else 0, end_time + ) + + if pod is not None: + batches: Iterator[List[DeploymentLogEvent]] = pod_pages(pod) + else: + pods = self.get_deployment_pods(deployment_id, revision_number) + streams = {name: _PodLogStream(pages=pod_pages(name)) for name in pods} + batches = self._merge_pod_streams(streams, newest_first) + + pending: List[DeploymentLogEvent] = [] + for batch in batches: + if newest_first: + # Each batch is entirely older than everything pending, so prepending + # keeps pending ascending while chunks are cut from its newest end. + pending[:0] = batch + while len(pending) >= chunk_size: + yield pending[-chunk_size:] + del pending[-chunk_size:] + else: + for event in batch: + # A late arrival re-delivered inside the look-behind span can sort + # below lines already pending; insort keeps every chunk ascending. + if pending and (event.timestamp, event.id) < (pending[-1].timestamp, pending[-1].id): + insort(pending, event, key=lambda pending_event: (pending_event.timestamp, pending_event.id)) + else: + pending.append(event) + while len(pending) >= chunk_size: + yield pending[:chunk_size] + del pending[:chunk_size] + if pending: + yield pending + + def _merge_pod_streams( + self, streams: Dict[str, _PodLogStream], newest_first: bool + ) -> Iterator[List[DeploymentLogEvent]]: + """Merge per-pod page iterators into (timestamp, id)-ascending batches that + arrive oldest-first (or newest-first) across batches. + + Strict cross-pod order while any pod is still fetching: reading forward, + release only lines at or below the least-advanced pod's frontier (its newest + buffered timestamp); a lagging pod's buffered lines are all at or below its + own frontier, so the minimum-frontier pod drains fully every round and the + merge cannot deadlock. Reading backward the roles mirror: a pod's frontier + is its oldest buffered timestamp, the watermark is the maximum frontier, and + lines at or above it are released — the maximum-frontier pod drains fully.""" + buffer_limit = LOG_MERGE_BUFFER_PAGES * MAX_LOG_PAGE_LINES while True: - if follow and pod is None and time.monotonic() - last_refresh >= LOG_POD_REFRESH_SECONDS: - last_refresh = time.monotonic() - listed = self.get_deployment_pods(deployment_id, revision_number) - for name in listed: - if name not in tails: - # a retired pod that reappears resumes from its own dedup window, - # so nothing it already delivered is re-yielded - tails[name] = retired.pop(name, _PodLogTail()) - - for name, tail in list(tails.items()): - if len(tail.buffer) >= buffer_limit: + for stream in streams.values(): + if stream.exhausted or len(stream.buffer) >= buffer_limit: continue # backpressure: let the merge watermark catch up before fetching more - if tail.caught_up and (not follow or time.monotonic() < tail.next_poll_at): + page = next(stream.pages, None) + if page is None: + stream.exhausted = True continue - page = self.get_deployment_logs( - deployment_id, revision_number, name, after=tail.held or initial_boundary, max_lines=max_lines - ) - if not page: - tail.caught_up = True - tail.next_poll_at = time.monotonic() + poll_interval - if follow and pod is None and name not in listed and not tail.buffer: - # gone from the pod list and caught up: stop polling it — it was - # not gating the watermark, so nothing waits on its removal - retired[name] = tails.pop(name) - continue - tail.caught_up = False - for raw in page: - event = DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=name) - if tail.held and event.id <= tail.held[-1].id: - # Late arrival inside the look-behind span: keep the held window - # id-ordered (id order == time order) so trimming stays correct. - insort(tail.held, event, key=lambda held_event: held_event.id) - else: - tail.held.append(event) - # Anchoring at start_time - 1 re-delivers the look-behind span below - # start_time; those ids must be held for dedup but never emitted. - if start_time is None or event.timestamp >= start_time: - if tail.buffer and event.id <= tail.buffer[-1].id: - insort(tail.buffer, event, key=lambda buffered_event: buffered_event.id) + if newest_first: + # Backward pages are entirely older than everything buffered. + stream.buffer[:0] = page + stream.frontier = stream.buffer[0].timestamp + else: + for event in page: + if stream.buffer and event.id <= stream.buffer[-1].id: + insort(stream.buffer, event, key=lambda buffered_event: buffered_event.id) else: - tail.buffer.append(event) - tail.held = _recent_anchor(tail.held) - tail.frontier = tail.held[-1].timestamp - - # The dedup window (~15s of server re-delivery) and the merge delay are two - # different concerns: the former decides what `held` keeps for the anchor, - # the latter only how long a fetched line waits so concurrent pods interleave. - lagging = [tail.frontier for tail in tails.values() if not tail.caught_up] - if lagging: - watermark = min(lagging) # catching up: strict cross-pod order - elif not follow or len(tails) <= 1: - # every pod caught up with nothing to merge against: release everything — - # follow=False must drain fully before returning, and a single-pod tail - # must not invent latency the old single-stream reader never had - watermark = None - else: - # steady-state multi-pod tail: hold a line just long enough for the - # peers' pages to arrive. Client wall clock against server timestamps: - # skew only shifts this interleave window, never drops a line. - watermark = int(time.time() * 1000) - merge_delay_ms + stream.buffer.append(event) + stream.frontier = stream.buffer[-1].timestamp + + active = [stream.frontier for stream in streams.values() if not stream.exhausted] + watermark = (max(active) if newest_first else min(active)) if active else None ready: List[DeploymentLogEvent] = [] - for tail in tails.values(): - cut = 0 - while cut < len(tail.buffer) and (watermark is None or tail.buffer[cut].timestamp <= watermark): - cut += 1 - if cut: - ready += tail.buffer[:cut] - del tail.buffer[:cut] + for stream in streams.values(): + if newest_first: + cut = len(stream.buffer) + while cut > 0 and (watermark is None or stream.buffer[cut - 1].timestamp >= watermark): + cut -= 1 + ready += stream.buffer[cut:] + del stream.buffer[cut:] + else: + cut = 0 + while cut < len(stream.buffer) and (watermark is None or stream.buffer[cut].timestamp <= watermark): + cut += 1 + ready += stream.buffer[:cut] + del stream.buffer[:cut] ready.sort(key=lambda event: (event.timestamp, event.id)) - yield from ready - - if not follow: - if all(tail.caught_up for tail in tails.values()): - return - continue - now = time.monotonic() - if any( - len(tail.buffer) < buffer_limit and (not tail.caught_up or now >= tail.next_poll_at) - for tail in tails.values() - ): - continue # something is fetchable right now - next_wake = min( - (tail.next_poll_at for tail in tails.values() if len(tail.buffer) < buffer_limit), - default=now + poll_interval, - ) - time.sleep(max(0.0, min(next_wake - now, poll_interval))) + if ready: + yield ready + if watermark is None: + return def deployment_log_session( self, deployment_id: int, revision_number: int, pod: str, events: Optional[list] = None ) -> "DeploymentLogSession": - """Stateful reader for one pod's logs that tracks fetched pages and anchors + """Deprecated: use fetch_logs() instead. + + Stateful reader for one pod's logs that tracks fetched pages and anchors every request itself — see DeploymentLogSession. Seed events with logs a previous session (or get_deployment_logs) returned for the same pod.""" return DeploymentLogSession(self, deployment_id, revision_number, pod, events) class DeploymentLogSession: - """Maintains a contiguous, ordered window of one pod's logs across fetches. + """Deprecated: use CentMLClient.fetch_logs() instead. + Maintains a contiguous, ordered window of one pod's logs across fetches. Every fetch is anchored on the window itself, so pages can never overlap or leave gaps inside it (within log retention; an undetectable gap forms if the session idles past retention before fetching newer lines). @@ -516,6 +635,11 @@ class DeploymentLogSession: # pylint: disable=R0917 def __init__(self, client: CentMLClient, deployment_id: int, revision_number: int, pod: str, events=None): + warnings.warn( + "DeploymentLogSession is deprecated; use CentMLClient.fetch_logs() instead", + DeprecationWarning, + stacklevel=2, + ) self._client = client self._deployment_id = deployment_id self._revision_number = revision_number @@ -535,7 +659,7 @@ def fetch_older(self, max_lines: int = DEFAULT_LOG_PAGE_LINES) -> list: """Fetch the page older than the window and prepend it; on an empty session fetches the newest page (tail). Returns the page; empty list = no older lines exist (yet).""" - page = self._client.get_deployment_logs( + page = self._client._fetch_log_page( # pylint: disable=protected-access self._deployment_id, self._revision_number, self._pod, @@ -553,7 +677,7 @@ def fetch_newer(self, max_lines: int = DEFAULT_LOG_PAGE_LINES) -> list: tailing. Rare late arrivals sort into the window below its newest lines.""" if not self._events: return self.fetch_older(max_lines=max_lines) - delta = self._client.get_deployment_logs( + delta = self._client._fetch_log_page( # pylint: disable=protected-access self._deployment_id, self._revision_number, self._pod, diff --git a/tests/pytest.ini b/tests/pytest.ini index bbeb447..af211bd 100644 --- a/tests/pytest.ini +++ b/tests/pytest.ini @@ -4,6 +4,7 @@ env = CENTML_CACHE_DIR=/tmp/centml-test filterwarnings = ignore::UserWarning + ignore:.*use (CentMLClient.)?fetch_logs.. instead:DeprecationWarning markers = gpu: this test needs the gpu to run quickly diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index e02e0bd..58c6712 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -1,5 +1,4 @@ -import time -from contextlib import contextmanager +import warnings from types import SimpleNamespace from unittest.mock import MagicMock, patch @@ -15,7 +14,13 @@ ) from centml.sdk import ApiException -from centml.sdk.api import LOG_DEDUP_RETENTION_MS, LOG_MERGE_BUFFER_PAGES, CentMLClient, get_centml_client +from centml.sdk.api import ( + LOG_DEDUP_RETENTION_MS, + LOG_MERGE_BUFFER_PAGES, + MAX_LOG_PAGE_LINES, + CentMLClient, + get_centml_client, +) from centml.sdk.config import settings @@ -637,43 +642,11 @@ def test_log_session_long_window_keeps_boundary_and_dedup_correct(): assert call.kwargs["fetch_newer"] is False and call.kwargs["timestamp"] == 1 -class _FakeClock: - """Deterministic stand-in for time.monotonic/time.time/time.sleep in follow-mode tests.""" - - EPOCH = 1_700_000_000.0 # wall-clock base at epoch scale, for the merge-delay watermark - - def __init__(self, max_sleeps=100): - self.now = 0.0 - self.sleeps = 0 - self._max_sleeps = max_sleeps - - def monotonic(self): - return self.now - - def time(self): - return self.EPOCH + self.now - - def wall_ms(self): - return int(self.time() * 1000) +def _flatten(chunks): + return [event for chunk in chunks for event in chunk] - def sleep(self, seconds): - self.sleeps += 1 - if self.sleeps > self._max_sleeps: - raise TimeoutError("test exceeded its sleep budget") - self.now += seconds - -@contextmanager -def _patched_clock(clock): - with ( - patch("centml.sdk.api.time.monotonic", clock.monotonic), - patch("centml.sdk.api.time.time", clock.time), - patch("centml.sdk.api.time.sleep", clock.sleep), - ): - yield clock - - -def test_iter_deployment_logs_yields_first_page_before_fetching_the_next(): +def test_fetch_logs_yields_first_chunk_before_fetching_the_next_page(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), @@ -682,21 +655,64 @@ def test_iter_deployment_logs_yields_first_page_before_fetching_the_next(): ] client = CentMLClient(api) - stream = client.iter_deployment_logs(123, 2, pod="pod-a") + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=2) first = next(stream) - assert first.id == "1-a" and first.pod == "pod-a" + assert [(e.id, e.pod) for e in first] == [("1-a", "pod-a"), ("2-b", "pod-a")] assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 1 # The first fetch never passes an (invalid) empty anchor list: it is a bare - # int boundary reading from the head of the log window. + # int boundary just below start_time (after is exclusive). first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] assert first_call.kwargs["fetch_newer"] is True and first_call.kwargs["timestamp"] == 0 - assert [e.id for e in stream] == ["2-b", "3-c"] + assert [[e.id for e in chunk] for chunk in stream] == [["3-c"]] assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 3 -def test_iter_deployment_logs_terminates_when_caught_up_without_sleeping(): +def test_fetch_logs_chunk_size_shapes_the_yields(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(*(_log_event(f"{1000 + i}-x", 1000 + i) for i in range(7))), + _log_page(), + ] + client = CentMLClient(api) + + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=3)) + + assert [len(chunk) for chunk in chunks] == [3, 3, 1] + assert [e.id for e in _flatten(chunks)] == [f"{1000 + i}-x" for i in range(7)] + + +def test_fetch_logs_defaults_read_full_retained_history_oldest_first(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 6)] + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) + client = CentMLClient(api) + + events = _flatten(client.fetch_logs(123, 2, pod="pod-a")) + + assert [e.id for e in events] == [e.id for e in all_events] + # An unbounded start scans forward from the head of the retained window. + first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] + assert first_call.kwargs["fetch_newer"] is True and first_call.kwargs["timestamp"] == 0 + + +def test_fetch_logs_end_time_truncates_the_window_and_stops_fetching(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + [_log_event(f"{1000 * i}-x", 1000 * i) for i in range(1, 9)] + ) + client = CentMLClient(api) + + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=2000, end_time=5000)) + + assert [e.id for e in events] == ["2000-x", "3000-x", "4000-x", "5000-x"] + # The page carrying lines past end_time already proves the window is complete: + # no further request is issued. + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 1 + + +def test_fetch_logs_terminates_when_caught_up(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ _log_page(_log_event("1-a", 1000)), @@ -704,44 +720,52 @@ def test_iter_deployment_logs_terminates_when_caught_up_without_sleeping(): ] client = CentMLClient(api) - with patch("centml.sdk.api.time.sleep") as sleep: - events = list(client.iter_deployment_logs(123, 2, pod="pod-a")) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1)) assert [e.id for e in events] == ["1-a"] - sleep.assert_not_called() + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 2 -def _replaying_log_server(all_events, look_behind_ms=15_000): - """Mimic the server: newer-than-boundary lines up to max_lines, plus the - re-delivered look-behind span at and before the boundary (uncounted).""" +def _replaying_log_server(all_events, look_behind_ms=15_000, page_cap=None): + """Mimic the server for both directions. fetch_newer: newer-than-boundary lines + up to max_lines, plus the re-delivered look-behind span at and before the + boundary (uncounted). Otherwise: the newest max_lines strictly older than the + boundary (no look-behind), or the tail page when the boundary is None. + page_cap simulates a server that fills pages with fewer lines than asked.""" def respond(**kwargs): + limit = min(kwargs["max_lines"], page_cap or kwargs["max_lines"]) boundary = kwargs["timestamp"] - newer = [e for e in all_events if e.timestamp > boundary][: kwargs["max_lines"]] - gray = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] - return _log_page(*sorted(gray + newer, key=lambda e: e.id)) + if kwargs["fetch_newer"]: + newer = [e for e in all_events if e.timestamp > boundary][:limit] + gray = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] + return _log_page(*sorted(gray + newer, key=lambda e: e.id)) + older = all_events if boundary is None else [e for e in all_events if e.timestamp < boundary] + return _log_page(*older[-limit:]) return respond -def test_iter_deployment_logs_does_not_livelock_on_gray_span_redelivery(): +def test_fetch_logs_does_not_livelock_on_gray_span_redelivery(): # Regression: with a bare int boundary the re-delivered look-behind span keeps # every page non-empty forever (measured against dev: 9 iterations of the same - # 7 gray lines before the naive port was declared wedged). The generator holds - # the trailing events, so the gray span dedupes away and the stream terminates. + # 7 gray lines before the naive port was declared wedged). The window iterator + # holds the trailing events, so the gray span dedupes away and the read terminates. all_events = [_log_event(f"{1000 + i:05d}-x", 1000 + i) for i in range(30)] api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=10 + ) client = CentMLClient(api) - events = list(client.iter_deployment_logs(123, 2, pod="pod-a", max_lines=10)) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1)) assert [e.id for e in events] == [e.id for e in all_events] # every line once, in order # 3 data pages + 1 empty page proving catch-up; a livelock would exceed this. assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 4 -def test_iter_deployment_logs_start_time_holds_gray_lines_below_the_window(): +def test_fetch_logs_start_time_holds_gray_lines_below_the_window(): all_events = [ _log_event("04990-w", 4990), _log_event("04995-x", 4995), @@ -752,7 +776,7 @@ def test_iter_deployment_logs_start_time_holds_gray_lines_below_the_window(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) client = CentMLClient(api) - events = list(client.iter_deployment_logs(123, 2, pod="pod-a", start_time=5000)) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=5000)) # The look-behind lines below start_time are held for dedup but never emitted. assert [e.id for e in events] == ["05000-y", "06000-z"] @@ -760,7 +784,7 @@ def test_iter_deployment_logs_start_time_holds_gray_lines_below_the_window(): assert first_call.kwargs["timestamp"] == 4999 # after is exclusive: admits start_time itself -def test_iter_deployment_logs_held_state_stays_within_the_dedup_window(): +def test_fetch_logs_held_state_stays_within_the_dedup_window(): step_ms = 10_000 pages = [ _log_page(*(_log_event(f"{(p * 100 + i) * step_ms:09d}-x", (p * 100 + i) * step_ms) for i in range(100))) @@ -771,22 +795,22 @@ def test_iter_deployment_logs_held_state_stays_within_the_dedup_window(): client = CentMLClient(api) anchor_sizes = [] - original = CentMLClient.get_deployment_logs + original = CentMLClient._fetch_log_page - def spying_get_deployment_logs(self, *args, **kwargs): + def spying_fetch_log_page(self, *args, **kwargs): if isinstance(kwargs.get("after"), list): anchor_sizes.append(len(kwargs["after"])) return original(self, *args, **kwargs) - with patch.object(CentMLClient, "get_deployment_logs", spying_get_deployment_logs): - events = list(client.iter_deployment_logs(123, 2, pod="pod-a")) + with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1)) assert len(events) == 4900 # Held state is the trimmed dedup window, not the accumulated stream. assert max(anchor_sizes) <= LOG_DEDUP_RETENTION_MS // step_ms + 1 -def test_iter_deployment_logs_merges_pods_by_timestamp_then_id(): +def test_fetch_logs_merges_pods_by_timestamp_then_id(): api = MagicMock() api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( pods=["pod-a", "pod-b"] @@ -802,301 +826,412 @@ def pages(**kwargs): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages client = CentMLClient(api) - events = list(client.iter_deployment_logs(123, 2)) + events = _flatten(client.fetch_logs(123, 2, start_time=1)) assert [(e.id, e.pod) for e in events] == [("1-a", "pod-a"), ("2-b", "pod-b"), ("3-a", "pod-a"), ("4-b", "pod-b")] api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_called_once() -def test_iter_deployment_logs_returns_empty_when_no_pod_has_logged(): +def test_fetch_logs_returns_empty_when_no_pod_has_logged(): api = MagicMock() api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace(pods=[]) client = CentMLClient(api) - assert not list(client.iter_deployment_logs(123, 2)) + assert not list(client.fetch_logs(123, 2, start_time=1)) api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() -def test_iter_deployment_logs_follow_polls_at_the_poll_interval(): +def test_fetch_logs_backpressures_a_pod_far_ahead_of_the_watermark(): + # A terminated old pod gates the watermark while a live pod's history is far newer; + # without backpressure every old-pod round would buffer another new-pod page, growing + # the merge buffer with the live pod's whole history. api = MagicMock() - responses = iter([_log_page(_log_event("1-a", 1000))]) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = lambda **kwargs: next( - responses, _log_page() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-old", "pod-new"] ) + old_count, new_count = 3 * MAX_LOG_PAGE_LINES, 5 * MAX_LOG_PAGE_LINES + events = { + "pod-old": [_log_event(f"old-{i:07d}", 1_000_000 + i) for i in range(old_count)], + "pod-new": [_log_event(f"new-{i:07d}", 100_000_000 + i) for i in range(new_count)], + } + + def pages(**kwargs): + newer = [e for e in events[kwargs["pod"]] if e.timestamp > kwargs["timestamp"]] + return _log_page(*newer[: kwargs["max_lines"]]) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages client = CentMLClient(api) - clock = _FakeClock(max_sleeps=3) - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True, poll_interval=2.0) - assert next(stream).id == "1-a" - with pytest.raises(TimeoutError): - next(stream) + calls = {"pod-old": 0, "pod-new": 0} + new_calls_while_old_active = [0] + original = CentMLClient._fetch_log_page + + def spying_fetch_log_page(self, *args, **kwargs): + calls[args[2]] += 1 + if args[2] == "pod-old": + new_calls_while_old_active[0] = calls["pod-new"] + return original(self, *args, **kwargs) - # One request per poll interval once caught up — no hot spinning. - assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == clock.sleeps + 1 + with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): + yielded = _flatten(client.fetch_logs(123, 2, start_time=1, chunk_size=MAX_LOG_PAGE_LINES)) + + assert [e.id for e in yielded] == [e.id for e in events["pod-old"]] + [e.id for e in events["pod-new"]] + # While the old pod was still draining, the new pod was fetched at most its buffer + # cap (LOG_MERGE_BUFFER_PAGES pages), not once per round. + assert new_calls_while_old_active[0] <= LOG_MERGE_BUFFER_PAGES + assert calls["pod-new"] == new_count // MAX_LOG_PAGE_LINES + 1 # data pages + 1 empty, none wasted -def test_iter_deployment_logs_follow_delivers_lines_appended_later(): +def test_fetch_logs_validates_eagerly_at_the_call_not_the_first_next(): api = MagicMock() - responses = iter([_log_page(_log_event("1-a", 1000)), _log_page(), _log_page(_log_event("2-b", 2000))]) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = lambda **kwargs: next( - responses, _log_page() - ) client = CentMLClient(api) - clock = _FakeClock() - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) - assert next(stream).id == "1-a" - assert next(stream).id == "2-b" + # Each ValueError is raised by the call itself — never deferred to next() — + # so a stored or passed-around iterator cannot surface it far from the bad call. + for kwargs in ({"start_time": 2000, "end_time": 1000}, {"start_time": -1}, {"end_time": -1}, {"chunk_size": 0}): + with pytest.raises(ValueError): + client.fetch_logs(123, 2, pod="pod-a", **kwargs) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() -def test_iter_deployment_logs_follow_picks_up_pods_that_appear_later(): +def test_fetch_logs_is_lazy_until_the_first_next(): api = MagicMock() - pod_lists = iter([["pod-a"]]) - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.side_effect = lambda **kwargs: ( - SimpleNamespace(pods=next(pod_lists, ["pod-a", "pod-b"])) + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a"] ) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page(_log_event("1-a", 1000)) + client = CentMLClient(api) - def pages(**kwargs): - if kwargs["pod"] == "pod-a": - return _log_page(_log_event("1-a", 1000)) if not kwargs["timestamp"] else _log_page() - return _log_page(_log_event("2-b", 2000)) if not kwargs["timestamp"] else _log_page() + stream = client.fetch_logs(123, 2) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + # Nothing — not even pod discovery — is fetched before the first next(). + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_not_called() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() + + next(stream) + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_called_once() + + +def test_deprecated_log_readers_warn_and_name_the_replacement(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace(pods=[]) client = CentMLClient(api) - clock = _FakeClock() - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) - assert next(stream).id == "1-a" - appeared = next(stream) + with pytest.warns(DeprecationWarning, match="fetch_logs"): + client.get_deployment_logs(123, 2, pod="pod-a") + with pytest.warns(DeprecationWarning, match="fetch_logs"): + client.get_deployment_logs_range(123, 2) + with pytest.warns(DeprecationWarning, match="fetch_logs"): + session = client.deployment_log_session(123, 2, "pod-a") - assert (appeared.id, appeared.pod) == ("2-b", "pod-b") - assert api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.call_count >= 2 + # The deprecated paths still work, and a constructed session fetches without + # re-warning on the SDK's own internal page calls. + with warnings.catch_warnings(): + warnings.simplefilter("error", DeprecationWarning) + assert session.fetch_older() == [] -def test_iter_deployment_logs_follow_does_not_gate_on_a_caught_up_silent_pod(): +def test_fetch_logs_does_not_warn_on_its_own_internal_calls(): api = MagicMock() api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( pods=["pod-a", "pod-b"] ) - pod_a_pages = iter( - [_log_page(_log_event("1-a", 1000), _log_event("3-a", 3000)), _log_page(_log_event("4-a", 4000))] - ) def pages(**kwargs): - if kwargs["pod"] == "pod-a": - return next(pod_a_pages, _log_page()) - return _log_page(_log_event("2-b", 2000)) if not kwargs["timestamp"] else _log_page() + if kwargs["timestamp"]: + return _log_page() + return _log_page(_log_event(f"1-{kwargs['pod']}", 1000)) api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages client = CentMLClient(api) - clock = _FakeClock() - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) - # Round one: pod-b's frontier (2000) gates 3-a. After pod-b polls empty it is - # caught up and stops gating, so pod-a's lines flow without any hold window. - assert [next(stream).id for _ in range(4)] == ["1-a", "2-b", "3-a", "4-a"] + with warnings.catch_warnings(): + warnings.simplefilter("error", DeprecationWarning) + events = _flatten(client.fetch_logs(123, 2, start_time=1)) + assert len(events) == 2 -def test_iter_deployment_logs_backpressures_a_pod_far_ahead_of_the_watermark(): - # A terminated old pod gates the watermark while a live pod's history is far newer; - # without backpressure every old-pod round would buffer another new-pod page, growing - # the merge buffer with the live pod's whole history. + +def _multi_pod_log_server(events_by_pod, **server_kwargs): + responders = {pod: _replaying_log_server(events, **server_kwargs) for pod, events in events_by_pod.items()} + + def respond(**kwargs): + return responders[kwargs["pod"]](**kwargs) + + return respond + + +def test_fetch_logs_newest_first_unbounded_walks_back_to_history_start(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 8)] api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-old", "pod-new"] + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=3 ) - events = { - "pod-old": [_log_event(f"old-{i:04d}", 1000 + i) for i in range(100)], - "pod-new": [_log_event(f"new-{i:04d}", 10_000_000 + i) for i in range(100)], - } + client = CentMLClient(api) - def pages(**kwargs): - newer = [e for e in events[kwargs["pod"]] if e.timestamp > (kwargs["timestamp"] or 0)] - return _log_page(*newer[: kwargs["max_lines"]]) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", newest_first=True, chunk_size=3)) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages - client = CentMLClient(api) + # Chunks walk toward older times; lines inside every chunk stay ascending. + assert [[e.id for e in chunk] for chunk in chunks] == [ + ["05000-x", "06000-x", "07000-x"], + ["02000-x", "03000-x", "04000-x"], + ["01000-x"], + ] + # An unbounded end starts at the tail page: no boundary at all. + first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] + assert first_call.kwargs["fetch_newer"] is False and first_call.kwargs["timestamp"] is None - calls = {"pod-old": 0, "pod-new": 0} - new_calls_while_old_active = [] - original = CentMLClient.get_deployment_logs - def spying_get_deployment_logs(self, *args, **kwargs): - calls[args[2]] += 1 - if args[2] == "pod-old": - new_calls_while_old_active.append(calls["pod-new"]) - return original(self, *args, **kwargs) +def test_fetch_logs_newest_first_stops_at_start_time(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 9)] + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=3 + ) + client = CentMLClient(api) - with patch.object(CentMLClient, "get_deployment_logs", spying_get_deployment_logs): - yielded = list(client.iter_deployment_logs(123, 2, max_lines=10)) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=3000, newest_first=True, chunk_size=3)) - assert [e.id for e in yielded] == [e.id for e in events["pod-old"]] + [e.id for e in events["pod-new"]] - # While the old pod was still draining, the new pod was fetched at most its buffer - # cap (LOG_MERGE_BUFFER_PAGES pages), not once per round. - assert max(new_calls_while_old_active) <= LOG_MERGE_BUFFER_PAGES - assert calls["pod-new"] == 11 # 10 data pages + 1 empty page, none wasted on re-polls + assert [e.id for e in _flatten(chunks)] == ["06000-x", "07000-x", "08000-x", "03000-x", "04000-x", "05000-x"] + # The page that crossed below start_time already proves the window is complete. + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 3 -def test_iter_deployment_logs_follow_single_pod_appends_late_arrivals(): - # A line that reaches the log store late is re-delivered with a fresh id and yields - # after newer lines — visible late delivery, where the CloudWatch path dropped it. +def test_fetch_logs_newest_first_end_time_bounds_the_first_page(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 9)] api = MagicMock() - responses = iter( - [ - _log_page(*(_log_event(f"{1000 + i}-x", 1000 + i) for i in range(5))), - _log_page(_log_event("1002-late", 1002), _log_event("2000-f", 2000)), - ] - ) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = lambda **kwargs: next( - responses, _log_page() - ) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) client = CentMLClient(api) - clock = _FakeClock() - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) - got = [next(stream).id for _ in range(7)] + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", end_time=5000, newest_first=True)) - assert got == ["1000-x", "1001-x", "1002-x", "1003-x", "1004-x", "1002-late", "2000-f"] + assert [e.id for e in events] == [f"{1000 * i:05d}-x" for i in range(1, 6)] + # before is exclusive: end_time + 1 admits lines at end_time itself. + first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] + assert first_call.kwargs["fetch_newer"] is False and first_call.kwargs["timestamp"] == 5001 -def test_iter_deployment_logs_drains_lines_newer_than_the_merge_delay_on_return(): - # follow=False must drain the merge buffers unconditionally once every pod is caught - # up; lines newer than any time-based watermark must not be silently dropped. - recent_ms = int(time.time() * 1000) + 60_000 +def test_fetch_logs_newest_first_bounded_window_walks_end_to_start(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 9)] api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a", "pod-b"] + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=2 ) + client = CentMLClient(api) - def pages(**kwargs): - if kwargs["timestamp"]: - return _log_page() - if kwargs["pod"] == "pod-a": - return _log_page(_log_event("1000-a", 1000), _log_event(f"{recent_ms}-a", recent_ms)) - return _log_page(_log_event("500-b", 500)) + chunks = list( + client.fetch_logs(123, 2, pod="pod-a", start_time=2000, end_time=6000, newest_first=True, chunk_size=2) + ) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages - client = CentMLClient(api) + assert [[e.id for e in chunk] for chunk in chunks] == [["05000-x", "06000-x"], ["03000-x", "04000-x"], ["02000-x"]] - events = list(client.iter_deployment_logs(123, 2)) - assert [e.id for e in events] == ["500-b", "1000-a", f"{recent_ms}-a"] +def test_fetch_logs_single_millisecond_window_in_both_directions(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 4)] + for newest_first in (False, True): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events + ) + client = CentMLClient(api) + events = _flatten( + client.fetch_logs(123, 2, pod="pod-a", start_time=2000, end_time=2000, newest_first=newest_first) + ) -def test_iter_deployment_logs_follow_retires_pods_gone_from_the_pod_list(): - api = MagicMock() - pod_lists = iter([["pod-a", "pod-b"]]) - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.side_effect = lambda **kwargs: ( - SimpleNamespace(pods=next(pod_lists, ["pod-a"])) - ) - clock = _FakeClock() - calls = {"pod-a": 0, "pod-b": 0} - pod_b_pages = iter([_log_page(_log_event("500-b", 500))]) + assert [e.id for e in events] == ["02000-x"] - def pages(**kwargs): - clock.now += 0.5 # requests take wall time, letting poll pacing and refresh advance - calls[kwargs["pod"]] += 1 - if kwargs["pod"] == "pod-b": - return next(pod_b_pages, _log_page()) - step = calls["pod-a"] - return _log_page(_log_event(f"{10_000 + step}-a", 10_000 + step)) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages +def test_fetch_logs_chunks_never_exceed_chunk_size_and_only_the_last_is_partial(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 12)] + for newest_first in (False, True): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=4 + ) + client = CentMLClient(api) + + chunks = list(client.fetch_logs(123, 2, pod="pod-a", newest_first=newest_first, chunk_size=3)) + + assert [len(chunk) for chunk in chunks] == [3, 3, 3, 2] + assert all(chunk for chunk in chunks) + for chunk in chunks: + assert [(e.timestamp, e.id) for e in chunk] == sorted((e.timestamp, e.id) for e in chunk) + + +def test_fetch_logs_forward_late_arrival_lands_in_a_later_chunk_still_ascending(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("01000-a", 1000), _log_event("02000-b", 2000), _log_event("03000-c", 3000)), + # A late arrival re-delivered inside the look-behind span sorts below the + # pending line 03000-c; every chunk must still be internally ascending. + _log_page(_log_event("02500-l", 2500), _log_event("04000-d", 4000)), + _log_page(), + ] client = CentMLClient(api) - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) - first_batch = [next(stream) for _ in range(40)] - calls_b_after_retirement = calls["pod-b"] - second_batch = [next(stream) for _ in range(30)] + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=2)) - # pod-b left the pod list at the first refresh and was caught up: polling it stopped. - assert calls["pod-b"] == calls_b_after_retirement - # Its one line was delivered exactly once, and nothing else was lost or duplicated. - ids = [e.id for e in first_batch + second_batch] - assert ids.count("500-b") == 1 and len(set(ids)) == len(ids) + assert [[e.id for e in chunk] for chunk in chunks] == [["01000-a", "02000-b"], ["02500-l", "03000-c"], ["04000-d"]] -def test_iter_deployment_logs_follow_holds_steady_state_lines_for_the_merge_delay(): - # Multi-pod steady state: a residual line above a peer's frontier is released once - # the merge delay (one poll_interval) has passed, not held indefinitely and not - # released before its peers had a chance to interleave. +def test_fetch_logs_newest_first_uses_no_dedup_anchors_and_delivers_each_line_once(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 30)] api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a", "pod-b"] + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=7 ) - clock = _FakeClock() - fresh_ms = clock.wall_ms() - 10 - fetch_time = {} + client = CentMLClient(api) - def pages(**kwargs): - if kwargs["timestamp"]: - return _log_page() - if kwargs["pod"] == "pod-a": - fetch_time["fresh"] = clock.now - return _log_page(_log_event(f"{fresh_ms - 5000}-a", fresh_ms - 5000), _log_event(f"{fresh_ms}-a", fresh_ms)) - return _log_page(_log_event(f"{fresh_ms - 6000}-b", fresh_ms - 6000)) + anchors = [] + original = CentMLClient._fetch_log_page - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages - client = CentMLClient(api) + def spying_fetch_log_page(self, *args, **kwargs): + anchors.append((kwargs.get("before"), kwargs.get("after"))) + return original(self, *args, **kwargs) - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) - assert next(stream).id == f"{fresh_ms - 6000}-b" - assert next(stream).id == f"{fresh_ms - 5000}-a" - released = next(stream) + with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", newest_first=True)) - assert released.id == f"{fresh_ms}-a" - assert clock.now - fetch_time["fresh"] >= 2.0 # held for the merge delay, then released + delivered = [e.id for e in events] + assert sorted(delivered) == [e.id for e in all_events] + assert len(delivered) == len(set(delivered)) + # A backward read never carries dedup state: every boundary is a bare int (or + # None for the tail page) and the after anchor is never used. + assert all(after is None and (before is None or isinstance(before, int)) for before, after in anchors) -def test_iter_deployment_logs_follow_single_pod_releases_without_merge_delay(): +def test_fetch_logs_newest_first_merges_pods_newest_chunk_first(): api = MagicMock() - clock = _FakeClock() - fresh_ms = clock.wall_ms() - 10 - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ - _log_page(_log_event(f"{fresh_ms}-a", fresh_ms)) - ] + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-a", "pod-b"] + ) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _multi_pod_log_server( + { + "pod-a": [_log_event(f"{ts:05d}-a", ts) for ts in (1000, 3000, 5000)], + "pod-b": [_log_event(f"{ts:05d}-b", ts) for ts in (2000, 4000, 6000)], + } + ) client = CentMLClient(api) - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, pod="pod-a", follow=True) - assert next(stream).id == f"{fresh_ms}-a" + chunks = list(client.fetch_logs(123, 2, newest_first=True, chunk_size=2)) - assert clock.sleeps == 0 # released in its own fetch round: no invented tail latency + assert [[(e.id, e.pod) for e in chunk] for chunk in chunks] == [ + [("05000-a", "pod-a"), ("06000-b", "pod-b")], + [("03000-a", "pod-a"), ("04000-b", "pod-b")], + [("01000-a", "pod-a"), ("02000-b", "pod-b")], + ] -def test_iter_deployment_logs_follow_paces_caught_up_pods_while_a_peer_streams(): +def test_fetch_logs_newest_first_interleaved_pods_deliver_every_line_once_in_order(): + # Backward-merge deadlock probe: interleaved pods, small pages, many rounds. + events_by_pod = { + "pod-a": [_log_event(f"{ts:06d}-a", ts) for ts in range(1000, 100_000, 210)], + "pod-b": [_log_event(f"{ts:06d}-b", ts) for ts in range(1100, 100_000, 350)], + } api = MagicMock() api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( pods=["pod-a", "pod-b"] ) - clock = _FakeClock() - calls = {"pod-a": 0, "pod-b": 0} - - def pages(**kwargs): - clock.now += 0.5 # requests take wall time - calls[kwargs["pod"]] += 1 - if kwargs["pod"] == "pod-b": - return _log_page() # permanently idle - step = calls["pod-a"] - return _log_page(_log_event(f"{10_000 + step}-a", 10_000 + step)) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _multi_pod_log_server( + events_by_pod, page_cap=13 + ) + client = CentMLClient(api) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + chunks = list(client.fetch_logs(123, 2, newest_first=True, chunk_size=17)) + + flattened = _flatten(chunks) + expected = sorted((e for events in events_by_pod.values() for e in events), key=lambda e: (e.timestamp, e.id)) + # Every line exactly once; chunks internally ascending and strictly older across chunks. + assert sorted(e.id for e in flattened) == sorted(e.id for e in expected) + assert len(flattened) == len(expected) + previous_min = None + for chunk in chunks: + keys = [(e.timestamp, e.id) for e in chunk] + assert keys == sorted(keys) + if previous_min is not None: + assert keys[-1] < previous_min + previous_min = keys[0] + + +def test_fetch_logs_newest_first_backpressures_the_lagging_old_pod(): + # The backward mirror of the asymmetric layout: reading newest-first, the live + # pod with new timestamps gates the watermark while the terminated old pod's + # buffer would otherwise grow with its whole history. + api = MagicMock() + api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( + pods=["pod-old", "pod-new"] + ) + old_count, new_count = 3 * MAX_LOG_PAGE_LINES, 5 * MAX_LOG_PAGE_LINES + events = { + "pod-old": [_log_event(f"old-{i:07d}", 1_000_000 + i) for i in range(old_count)], + "pod-new": [_log_event(f"new-{i:07d}", 100_000_000 + i) for i in range(new_count)], + } + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _multi_pod_log_server(events) client = CentMLClient(api) - with _patched_clock(clock): - stream = client.iter_deployment_logs(123, 2, follow=True, poll_interval=2.0) - for _ in range(20): - next(stream) + calls = {"pod-old": 0, "pod-new": 0} + old_calls_while_new_active = [0] + original = CentMLClient._fetch_log_page + + def spying_fetch_log_page(self, *args, **kwargs): + calls[args[2]] += 1 + if args[2] == "pod-new": + old_calls_while_new_active[0] = calls["pod-old"] + return original(self, *args, **kwargs) + + with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): + yielded = _flatten(client.fetch_logs(123, 2, newest_first=True, chunk_size=MAX_LOG_PAGE_LINES)) + + def backward_page_order(pod_events): + pages = [pod_events[i : i + MAX_LOG_PAGE_LINES] for i in range(0, len(pod_events), MAX_LOG_PAGE_LINES)] + return [e.id for page in reversed(pages) for e in page] + + assert [e.id for e in yielded] == backward_page_order(events["pod-new"]) + backward_page_order(events["pod-old"]) + # While the new pod was still draining, the old pod was fetched at most its + # buffer cap (LOG_MERGE_BUFFER_PAGES pages), not once per round. + assert old_calls_while_new_active[0] <= LOG_MERGE_BUFFER_PAGES + assert calls["pod-old"] == old_count // MAX_LOG_PAGE_LINES + 1 # data pages + 1 empty, none wasted + + +def test_documented_tail_recipe_is_duplicate_free_and_memory_bounded(): + # The README tail recipe: re-call fetch_logs with the next window starting + # OVERLAP_MS below the newest seen line, dedup by id across calls, and trim + # the id set to the overlap window so it never grows with the stream. + overlap_ms = 30_000 + base = 1_000_000 + all_events = [_log_event(f"{base + i * 100:09d}-x", base + i * 100) for i in range(200)] + visible = [100] # grow between polls to simulate a live stream + api = MagicMock() + + def respond(**kwargs): + return _replaying_log_server(all_events[: visible[0]])(**kwargs) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = respond + client = CentMLClient(api) - # The idle pod is re-polled at most once per poll_interval of elapsed time, not once - # per round of its streaming peer. - assert calls["pod-b"] <= clock.now / 2.0 + 2 - assert calls["pod-b"] < calls["pod-a"] / 2 + delivered = [] + seen = {} + boundary = base # newest timestamp seen so far; the first window reads from base + peak_seen = 0 + for _ in range(4): + for chunk in client.fetch_logs( + 123, 2, pod="pod-a", start_time=max(boundary - overlap_ms, 0), newest_first=False + ): + for event in chunk: + if event.id in seen: + continue + seen[event.id] = event.timestamp + boundary = max(boundary, event.timestamp) + delivered.append(event.id) + cutoff = boundary - overlap_ms + seen = {event_id: ts for event_id, ts in seen.items() if ts >= cutoff} + peak_seen = max(peak_seen, len(seen)) + visible[0] = min(visible[0] + 50, len(all_events)) + + assert delivered == [e.id for e in all_events] # every line exactly once, in order + # The dedup state holds only the overlap window, not the whole stream. + assert peak_seen <= overlap_ms // 100 + 1 From a18513c44a8a22f77747d19b5213d88cba7e3014 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 09:10:22 -0400 Subject: [PATCH 08/22] Document fetch_logs directions and the bounded caller tail loop Rewrite the deployment-logs README section and the SDK example around the consolidated fetch_logs: unbounded-by-default windows, newest_first as chunk arrival order only (lines inside every chunk stay ascending), the backward-read completeness caveat, and tailing as repeated forward fetch_logs calls whose consecutive windows overlap by the server's ~15s late-arrival span, deduplicated by event.id with the id set trimmed to the overlap window so the loop's memory never grows with the stream. Extend the migration tables: 0.5.x start_from_head maps to newest_first, and the deprecated 0.6.0 readers each map to a fetch_logs form. Signed-off-by: Honglin Cao --- README.md | 147 ++++++++++++++++++---------- examples/sdk/get_deployment_logs.py | 84 ++++++++++------ 2 files changed, 150 insertions(+), 81 deletions(-) diff --git a/README.md b/README.md index 92388a7..7d22e3a 100644 --- a/README.md +++ b/README.md @@ -55,48 +55,88 @@ delete the deployment automatically. ### Deployment logs SDK example -`iter_deployment_logs()` streams a revision's logs lazily, oldest first, each line -exactly once, with bounded memory however long the log is — by default merging every -pod chronologically (each event carries its pod name). `follow=False` returns once -caught up; `follow=True` keeps tailing and picks up new pods of the revision as they -first log. `start_time` (epoch ms) bounds the beginning and `pod=` restricts to one -pod — discover names with `get_deployment_pods()` (terminated pods still within log -retention are included). Lines are yielded in timestamp order: cross-pod ordering is -strict while catching up on history; at the tip, concurrent pods interleave within -one `poll_interval`, a single-pod tail is released immediately, and a line reaching -the log store after its timestamp has passed that release point is appended rather -than inserted — so a single-pod follow appends any late line and a multi-pod follow -keeps order for lines under one `poll_interval` late. Such lines are still delivered -exactly once, within the server's ~15s re-delivery window; the previous -CloudWatch-based read path dropped them entirely. - -For non-streaming access: `get_deployment_logs_range()` fetches a specific time -window as a list (epoch-millisecond bounds, both optional; `pod=None` merges every -pod). A `deployment_log_session()` pages one pod statefully — `fetch_older()` toward -the beginning of history, `fetch_newer()` for only-new lines — keeping the merged, -ordered log in `.events`. The same paging is available statelessly through -`get_deployment_logs(before=..., after=...)`, anchored on events you already hold -or on a bare epoch-millisecond boundary: +`fetch_logs()` is the one way to read deployment logs: it fetches a revision's +stored log lines within a time window (`start_time`/`end_time`, epoch ms, +inclusive; omit either bound to leave that side unbounded) and yields them lazily +as chunks of up to `chunk_size` `DeploymentLogEvent` — each line at most once, +each event carrying its pod name, with bounded memory however large the window. +`newest_first` selects only the order chunks arrive: `False` (the default) walks +the window oldest chunk first, `True` newest chunk first; lines inside every chunk +are always in ascending `(timestamp, id)` order. So the bare call reads the full +retained history chronologically, `newest_first=True` starts from the newest +stored line and walks backward, and `start_time` alone catches up from a known +point to the present. By default every pod of the revision is merged into one +stream; pass `pod=` to read a single pod — discover names with +`get_deployment_pods()` (terminated pods still within log retention are included): -```bash -python examples/sdk/get_deployment_logs.py +```python +for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, start_time=t1_ms, end_time=t2_ms): + for event in chunk: + print(event.pod, event.message) ``` +The iterator always terminates, and its exhaustion is the only termination signal: +one that yields nothing means the window holds no stored lines (aged out of +retention, before the deployment existed, an unknown pod, or genuinely empty). +Reading backward, note that a line the log store receives late for a time region +the walk has already passed is absent from that call: everything older than +roughly the read's start minus the ingest lag (~15s) is complete, and when +completeness of the newest lines matters, read forward. There is no follow mode: +tailing is a caller loop that re-calls a forward `fetch_logs` with a later +`start_time` and deduplicates by `event.id`: + +```python +import time + +OVERLAP_MS = 30_000 # covers the server's ~15s late-arrival re-delivery span +POLL_SECONDS = 2.0 + +seen = {} # event id -> timestamp, trimmed to the overlap window each round +boundary = int(time.time() * 1000) # newest timestamp seen so far +while True: + for chunk in cclient.fetch_logs( + DEPLOYMENT_ID, REVISION, start_time=max(boundary - OVERLAP_MS, 0), newest_first=False + ): + for event in chunk: + if event.id in seen: + continue + seen[event.id] = event.timestamp + boundary = max(boundary, event.timestamp) + print(event.pod, event.message) + cutoff = boundary - OVERLAP_MS + seen = {event_id: ts for event_id, ts in seen.items() if ts >= cutoff} + time.sleep(POLL_SECONDS) +``` + +Two properties of this loop matter. Consecutive windows overlap on purpose: the log +store may deliver a line up to ~15 seconds after its timestamp, so starting each call +`OVERLAP_MS` below the newest seen line is what keeps late arrivals from being +skipped — do not advance `start_time` past that span to avoid the duplicates. And the +dedup state is bounded: only ids inside the overlap window can come back again, so +`seen` is trimmed to that window each round and never grows with the stream. + +`python examples/sdk/get_deployment_logs.py` runs a newest-first peek, a full +chronological read and this tail loop. `get_deployment_logs()`, `get_deployment_logs_range()` and +`deployment_log_session()` still work but are deprecated in favor of `fetch_logs()` +and raise a `DeprecationWarning` on use. + ### Migrating deployment log reads from 0.5.x -`get_deployment_logs()` kept its name but not its signature: `start_time`, `end_time`, -`line_count`, `start_from_head` and `stream` are gone, and logs are read per pod. A -0.5.x call raises `TypeError` (or a validation error, if its arguments were positional) -rather than returning something wrong, so no call site fails silently. +`get_deployment_logs()` kept its name but not its signature, and is now deprecated: +`start_time`, `end_time`, `line_count`, `start_from_head` and `stream` are gone, and +`fetch_logs()` is the replacement for every read. A 0.5.x call raises `TypeError` +(or a validation error, if its arguments were positional) rather than returning +something wrong, so no call site fails silently. -| To | 0.5.x | 0.6.0 | +| To | 0.5.x | now | |---|---|---| -| Read a time window | `get_deployment_logs(id, rev, start_time=, end_time=)` | `get_deployment_logs_range(id, rev, start_time=, end_time=)` | -| Stream a window lazily | the same call with `stream=True` | `iter_deployment_logs(id, rev, start_time=)` | -| Take the newest lines first | `start_from_head=False` | `get_deployment_logs(id, rev, pod)`, then page with `before=` | -| Cap a page | `line_count=n` | `max_lines=n`, at most 5000 | +| Read a time window | `get_deployment_logs(id, rev, start_time=, end_time=)` | `fetch_logs(id, rev, start_time=, end_time=)` | +| Stream a window lazily | the same call with `stream=True` | `fetch_logs(...)` — chunks are yielded as they are fetched | +| Take the newest lines first | `start_from_head=False` | `fetch_logs(id, rev, newest_first=True)` | +| Read from the beginning | `start_from_head=True` | `fetch_logs(id, rev)` — oldest first is the default | +| Cap what one iteration hands you | `line_count=n` | `chunk_size=n` | | Tell which pod a line came from | parse `kubernetes.pod_name` out of `message` | `event.pod` | -| Keep tailing past the window | not supported | `iter_deployment_logs(..., follow=True)` | +| Keep tailing past the window | not supported | re-call `fetch_logs` with overlapping windows (the tail loop above) | A whole-window read loses its envelope parsing, because `message` is now the log line itself rather than a JSON record wrapping it: @@ -108,13 +148,14 @@ for event in events: record = json.loads(event["message"]) print(record["kubernetes"]["pod_name"], record["log"]) -# 0.6.0 -for event in cclient.get_deployment_logs_range(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2): - print(event.pod, event.message) +# now +for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2): + for event in chunk: + print(event.pod, event.message) ``` -A `stream=True` loop becomes an `iter_deployment_logs()` loop, which yields each page as -it arrives just as the old generator did: +A `stream=True` loop becomes a `fetch_logs()` loop, which yields each chunk as it +arrives just as the old generator yielded pages: ```python # 0.5.x @@ -123,20 +164,26 @@ for event in cclient.get_deployment_logs( ): print(json.loads(event["message"])["log"]) -# 0.6.0 -for event in cclient.iter_deployment_logs(DEPLOYMENT_ID, REVISION, start_time=t1): - print(event.message) +# now +for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2): + for event in chunk: + print(event.message) ``` -Two contract changes to check error handling against: a revision that does not exist now -answers 404 where the old endpoint answered 400, and a `max_lines` above 5000 is rejected -before the request leaves the client. +One contract change to check error handling against: a revision that does not exist +now answers 404 where the old endpoint answered 400. + +The 0.6.0 readers — `get_deployment_logs()` page anchoring, `get_deployment_logs_range()` +and `deployment_log_session()` — still work but are deprecated and warn on use; the +look-behind anchoring they exposed is handled inside `fetch_logs()`: -When paging by hand with `get_deployment_logs(after=...)`, anchor on the events you already -hold rather than on a bare timestamp. Every fetch-newer call re-delivers a short look-behind -span so late-arriving lines are not missed; an events anchor lets the SDK drop the lines you -already have, while a bare-timestamp anchor re-delivers that span undeduplicated and, once -the reader has caught up, stops advancing. `iter_deployment_logs()` handles this for you. +| 0.6.0 | now | +|---|---| +| `get_deployment_logs(id, rev, pod)` — newest page of one pod | `fetch_logs(id, rev, pod=pod, newest_first=True)` and take the first chunk | +| `get_deployment_logs(id, rev, pod, after=events)` — page newer than held events | `fetch_logs(id, rev, pod=pod, start_time=boundary_ms)` (the tail loop above for repeated polling) | +| `get_deployment_logs_range(id, rev, start_time=, end_time=)` | `fetch_logs(id, rev, start_time=, end_time=)` — chunked and lazy instead of one list | +| `deployment_log_session(...).fetch_older()` loop | `fetch_logs(id, rev, pod=pod, newest_first=True)` — one iterator walks back to the start | +| `session.fetch_newer()` polling | the tail loop above | ### Un-installation diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index fa87e5f..9dafbbb 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -1,4 +1,4 @@ -import itertools +import time from datetime import datetime, timezone from centml.sdk.api import get_centml_client @@ -6,7 +6,10 @@ # --- Configuration --- DEPLOYMENT_ID = 1234 # Replace with your deployment ID REVISION_NUMBER = 10 -FOLLOW_LINES = 20 # How many tailed lines to print before stopping the follow +RECENT_LINES = 20 # How many of the newest stored lines to peek at +TAIL_LINES = 20 # How many tailed lines to print before stopping the tail loop +OVERLAP_MS = 30_000 # Covers the server's ~15s late-arrival re-delivery span +POLL_SECONDS = 2.0 def format_event(event) -> str: @@ -16,39 +19,58 @@ def format_event(event) -> str: def main(): with get_centml_client() as cclient: - # Stream the revision's full history, all pods merged chronologically. - # The iterator is lazy: pages are fetched as you consume it, and its held - # state stays bounded no matter how many lines stream by. - print(f"Logs for deployment {DEPLOYMENT_ID} revision {REVISION_NUMBER}:\n") + # The newest stored lines, without reading the whole history: newest_first + # walks the window backward, one chunk at a time. Direction changes only + # the order chunks arrive — lines inside each chunk are always ascending. + print(f"Newest {RECENT_LINES} lines of deployment {DEPLOYMENT_ID} revision {REVISION_NUMBER}:\n") + printed = 0 + for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION_NUMBER, newest_first=True, chunk_size=RECENT_LINES): + for event in chunk: + print(format_event(event)) + printed += len(chunk) + if printed >= RECENT_LINES: + break + + # A full chronological read, all pods merged. fetch_logs is lazy — chunks + # are yielded as they are fetched, with bounded memory however large the + # window — and always terminates once caught up. Bound the window with + # start_time/end_time (epoch ms, inclusive) when the history is long. count = 0 - for event in cclient.iter_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER): - print(format_event(event)) - count += 1 - print(f"\nCaught up after {count} lines.") - - # follow=True keeps tailing instead of returning: it re-polls caught-up pods - # every poll_interval seconds and picks up new pods of the revision as they - # first log. Stop by breaking out (or just abandon the iterator). - print(f"\nFollowing; stopping after {FOLLOW_LINES} new lines...") - stream = cclient.iter_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER, follow=True) - for event in itertools.islice(stream, FOLLOW_LINES): - print(format_event(event)) - - # A single pod (discover names with get_deployment_pods) or a bounded start: + for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION_NUMBER): + count += len(chunk) + print(f"\nFull retained history holds {count} lines.") + + # Tailing is a caller loop: re-call a forward fetch_logs with the next + # window starting OVERLAP_MS below the newest seen line, so lines the log + # store delivers late (up to ~15s after their timestamp) are not skipped, + # and deduplicate by event.id. Only ids inside the overlap window can come + # back again, so trimming `seen` to it keeps the loop's memory bounded. + print(f"\nTailing; stopping after {TAIL_LINES} new lines...") + seen = {} # event id -> timestamp, trimmed to the overlap window each round + boundary = int(time.time() * 1000) # newest timestamp seen so far + printed = 0 + while printed < TAIL_LINES: + for chunk in cclient.fetch_logs( + DEPLOYMENT_ID, REVISION_NUMBER, start_time=max(boundary - OVERLAP_MS, 0), newest_first=False + ): + for event in chunk: + if event.id in seen: + continue + seen[event.id] = event.timestamp + boundary = max(boundary, event.timestamp) + print(format_event(event)) + printed += 1 + cutoff = boundary - OVERLAP_MS + seen = {event_id: ts for event_id, ts in seen.items() if ts >= cutoff} + time.sleep(POLL_SECONDS) + + # A single pod (discover names with get_deployment_pods; terminated pods + # still within log retention are included), with caller-sized chunks: # pods = cclient.get_deployment_pods(DEPLOYMENT_ID, REVISION_NUMBER) - # for event in cclient.iter_deployment_logs( - # DEPLOYMENT_ID, REVISION_NUMBER, pod=pods[0], start_time=t1_ms + # for chunk in cclient.fetch_logs( + # DEPLOYMENT_ID, REVISION_NUMBER, pod=pods[0], start_time=t1_ms, end_time=t2_ms, chunk_size=500 # ): # ... - # A specific time window as a list (all pods merged, oldest first): - # window = cclient.get_deployment_logs_range( - # DEPLOYMENT_ID, REVISION_NUMBER, start_time=t1_ms, end_time=t2_ms - # ) - # Manual paging, anchored on events you already hold — useful when you - # manage storage yourself (deployment_log_session wraps this statefully): - # page = cclient.get_deployment_logs(DEPLOYMENT_ID, REVISION_NUMBER, pod=pods[0]) # tail - # older = cclient.get_deployment_logs(..., pod=pods[0], before=page) # empty return = beginning - # newer = cclient.get_deployment_logs(..., pod=pods[0], after=page) # empty return = nothing new if __name__ == "__main__": From 69ccb1a5612667041fdaa5679c1a2f6d2a5b9250 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 10:08:26 -0400 Subject: [PATCH 09/22] Mark the deprecated log readers with the PEP 702 decorator Signed-off-by: Honglin Cao --- centml/sdk/api.py | 20 ++++++++++---------- requirements.txt | 1 + tests/test_sdk_api.py | 8 +++++++- 3 files changed, 18 insertions(+), 11 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index eafbf76..4605313 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -19,6 +19,7 @@ InviteUserRequest, Metric, ) +from typing_extensions import deprecated from centml.sdk import auth from centml.sdk.config import settings @@ -250,6 +251,7 @@ def get_deployment_pods(self, deployment_id: int, revision_number: int) -> List[ ).pods # pylint: disable=R0917 + @deprecated("get_deployment_logs() is deprecated; use fetch_logs() instead") def get_deployment_logs( self, deployment_id: int, @@ -282,7 +284,6 @@ def get_deployment_logs( carries the 5000 nearest its direction (the newest when paging older, the oldest when paging newer), independently of max_lines. """ - warnings.warn("get_deployment_logs() is deprecated; use fetch_logs() instead", DeprecationWarning, stacklevel=2) return self._fetch_log_page( deployment_id, revision_number, pod, before=before, after=after, max_lines=max_lines ) @@ -336,6 +337,7 @@ def _fetch_log_page( return [event for event in response.events if event.id not in held_event_ids] # pylint: disable=R0917 + @deprecated("get_deployment_logs_range() is deprecated; use fetch_logs() instead") def get_deployment_logs_range( self, deployment_id: int, @@ -350,9 +352,6 @@ def get_deployment_logs_range( optional — an open end reads to the beginning or the present), oldest first. pod=None reads all pods of the revision and merges the streams chronologically; each returned event carries its pod name.""" - warnings.warn( - "get_deployment_logs_range() is deprecated; use fetch_logs() instead", DeprecationWarning, stacklevel=2 - ) if start_time is not None and end_time is not None and start_time > end_time: raise ValueError("start_time must not exceed end_time") @@ -613,6 +612,7 @@ def _merge_pod_streams( if watermark is None: return + @deprecated("deployment_log_session() is deprecated; use fetch_logs() instead") def deployment_log_session( self, deployment_id: int, revision_number: int, pod: str, events: Optional[list] = None ) -> "DeploymentLogSession": @@ -621,9 +621,14 @@ def deployment_log_session( Stateful reader for one pod's logs that tracks fetched pages and anchors every request itself — see DeploymentLogSession. Seed events with logs a previous session (or get_deployment_logs) returned for the same pod.""" - return DeploymentLogSession(self, deployment_id, revision_number, pod, events) + with warnings.catch_warnings(): + # This call already warned via its own decorator; constructing the + # (also-deprecated) session class must not warn a second time. + warnings.simplefilter("ignore", DeprecationWarning) + return DeploymentLogSession(self, deployment_id, revision_number, pod, events) +@deprecated("DeploymentLogSession is deprecated; use CentMLClient.fetch_logs() instead") class DeploymentLogSession: """Deprecated: use CentMLClient.fetch_logs() instead. @@ -635,11 +640,6 @@ class DeploymentLogSession: # pylint: disable=R0917 def __init__(self, client: CentMLClient, deployment_id: int, revision_number: int, pod: str, events=None): - warnings.warn( - "DeploymentLogSession is deprecated; use CentMLClient.fetch_logs() instead", - DeprecationWarning, - stacklevel=2, - ) self._client = client self._deployment_id = deployment_id self._revision_number = revision_number diff --git a/requirements.txt b/requirements.txt index 6629fff..1ccea02 100644 --- a/requirements.txt +++ b/requirements.txt @@ -7,3 +7,4 @@ websockets>=16.0 pyte>=0.8.0 platform-api-python-client==4.28.0 click>=8.4.1 +typing-extensions>=4.5 diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 58c6712..37cb9b5 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -19,6 +19,7 @@ LOG_MERGE_BUFFER_PAGES, MAX_LOG_PAGE_LINES, CentMLClient, + DeploymentLogSession, get_centml_client, ) from centml.sdk.config import settings @@ -924,8 +925,13 @@ def test_deprecated_log_readers_warn_and_name_the_replacement(): client.get_deployment_logs(123, 2, pod="pod-a") with pytest.warns(DeprecationWarning, match="fetch_logs"): client.get_deployment_logs_range(123, 2) - with pytest.warns(DeprecationWarning, match="fetch_logs"): + with pytest.warns(DeprecationWarning, match="fetch_logs") as caught: session = client.deployment_log_session(123, 2, "pod-a") + # Exactly one warning: the method's own, not a second from constructing the + # (also-deprecated) session class inside it. + assert len(caught) == 1 + with pytest.warns(DeprecationWarning, match="fetch_logs"): + DeploymentLogSession(client, 123, 2, "pod-a") # The deprecated paths still work, and a constructed session fetches without # re-warning on the SDK's own internal page calls. From 42b3f8b75f6318dbb1c2da87665a0993b0a6b860 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 10:08:51 -0400 Subject: [PATCH 10/22] Drop pylint disables for the globally disabled protected-access Signed-off-by: Honglin Cao --- centml/sdk/api.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 4605313..282b73b 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -659,7 +659,7 @@ def fetch_older(self, max_lines: int = DEFAULT_LOG_PAGE_LINES) -> list: """Fetch the page older than the window and prepend it; on an empty session fetches the newest page (tail). Returns the page; empty list = no older lines exist (yet).""" - page = self._client._fetch_log_page( # pylint: disable=protected-access + page = self._client._fetch_log_page( self._deployment_id, self._revision_number, self._pod, @@ -677,7 +677,7 @@ def fetch_newer(self, max_lines: int = DEFAULT_LOG_PAGE_LINES) -> list: tailing. Rare late arrivals sort into the window below its newest lines.""" if not self._events: return self.fetch_older(max_lines=max_lines) - delta = self._client._fetch_log_page( # pylint: disable=protected-access + delta = self._client._fetch_log_page( self._deployment_id, self._revision_number, self._pod, From 9ccc81aceafeffd7a0d8f9cdd2566f5e19650e92 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 10:35:16 -0400 Subject: [PATCH 11/22] Rework fetch_logs into a single-pod open-ended generator MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Per review on #152: pod is required, start_time defaults to the call time, and without end_time the generator never terminates — once caught up it yields an empty chunk instead of returning, keeping the dedup anchor alive so tailing needs no caller-side bookkeeping. newest_first, the backward walker, the multi-pod merge and _iter_log_chunks are removed; validation still raises at the call via a nested generator. Tests are cut to the reduced scope, the pytest.ini deprecation filter is replaced with pytest.warns at the call sites, and an open-ended empty-chunk test is added. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 305 ++++++---------------- tests/pytest.ini | 1 - tests/test_sdk_api.py | 571 +++++++++++------------------------------- 3 files changed, 217 insertions(+), 660 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 282b73b..0347ee2 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -1,8 +1,9 @@ +import time import warnings from bisect import insort from contextlib import contextmanager -from dataclasses import dataclass, field -from typing import Dict, Iterator, List, Optional, Union +from dataclasses import dataclass +from typing import Iterator, List, Optional, Union import platform_api_python_client from platform_api_python_client import ( @@ -31,12 +32,6 @@ # The server re-delivers a ~15s look-behind window on fetch-newer requests; only the # caller's events within this generous margin of the boundary can be re-delivered. LOG_DEDUP_RETENTION_MS = 300_000 -# Merge backpressure: a pod with this many pages buffered ahead of the merge watermark -# is not fetched further until the watermark catches up. Two pages keep the merge fed -# (one page draining while the next waits) yet cap the lookahead, so a pod far ahead -# in time — typically a live pod merged with a terminated predecessor — buffers a -# couple of pages instead of its whole history. -LOG_MERGE_BUFFER_PAGES = 2 def _recent_anchor(events: list) -> list: @@ -53,7 +48,7 @@ def _recent_anchor(events: list) -> list: @dataclass(frozen=True) class DeploymentLogEvent: """One log line with its pod attached — logs_v4 events carry no pod name, so - merged multi-pod views need the SDK to attribute each line itself.""" + the SDK attributes each line to the pod it was fetched from.""" id: str timestamp: int @@ -61,19 +56,6 @@ class DeploymentLogEvent: pod: str -@dataclass -class _PodLogStream: - """Per-pod merge state for fetch_logs: the pod's page iterator, its fetched-but- - unreleased events awaiting the merge watermark, its watermark contribution (the - newest buffered timestamp reading forward, the oldest reading backward), and - whether the iterator has finished its window.""" - - pages: Iterator[List[DeploymentLogEvent]] - buffer: List[DeploymentLogEvent] = field(default_factory=list) - frontier: int = -1 - exhausted: bool = False - - class CentMLClient: def __init__(self, api): self._api: platform_api_python_client.EXTERNALApi = api @@ -380,120 +362,43 @@ def get_deployment_logs_range( merged.sort(key=lambda event: event.id) return merged - def _iter_pod_log_pages( - self, deployment_id: int, revision_number: int, pod: str, start_ms: int, end_time: Optional[int] - ) -> Iterator[List[DeploymentLogEvent]]: - """Page one pod's logs within [start_ms, end_time] oldest first, yielding each - non-empty in-window page once. The held dedup anchor is trimmed to the server's - re-delivery span, so state never grows with the stream.""" - held: list = [] - # after is exclusive, so start_ms - 1 admits lines at start_ms itself; - # start_ms 0 means the whole log window — scan from the head. - initial_boundary = max(start_ms - 1, 0) - while True: - anchor: Union[list, int] = _recent_anchor(held) if held else initial_boundary - page = self._fetch_log_page(deployment_id, revision_number, pod, after=anchor, max_lines=MAX_LOG_PAGE_LINES) - if not page: - return - emitted: List[DeploymentLogEvent] = [] - past_end = False - for raw in page: - if held and raw.id <= held[-1].id: - # Late arrival inside the look-behind span: keep the held window - # id-ordered (id order == time order) so trimming stays correct. - insort(held, raw, key=lambda held_event: held_event.id) - else: - held.append(raw) - # Anchoring at start_ms - 1 re-delivers the look-behind span below - # start_ms; those ids must be held for dedup but never emitted. - if raw.timestamp < start_ms: - continue - if end_time is not None and raw.timestamp > end_time: - past_end = True - continue - emitted.append(DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod)) - held = _recent_anchor(held) - if emitted: - yield emitted - if past_end: - return - - def _iter_pod_log_pages_backward( - self, deployment_id: int, revision_number: int, pod: str, start_time: Optional[int], end_time: Optional[int] - ) -> Iterator[List[DeploymentLogEvent]]: - """Page one pod's logs within [start_time, end_time] newest page first, each - page internally oldest-first. A backward walk visits each time region once - and before pages carry no re-delivery span, so no dedup state is needed.""" - # before is exclusive, so end_time + 1 admits lines at end_time itself; no - # end_time means no boundary — the server answers with the tail page. - boundary: Optional[int] = None if end_time is None else end_time + 1 - while True: - page = self._fetch_log_page( - deployment_id, revision_number, pod, before=boundary, max_lines=MAX_LOG_PAGE_LINES - ) - if not page: - return - emitted = [ - DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod) - for raw in page - if start_time is None or raw.timestamp >= start_time - ] - if emitted: - yield emitted - if start_time is not None and page[0].timestamp < start_time: - return - # Pages never split a millisecond, so an exclusive boundary at the oldest - # delivered timestamp neither re-delivers nor skips. - boundary = page[0].timestamp - # pylint: disable=R0917 def fetch_logs( self, deployment_id: int, revision_number: int, - pod: Optional[str] = None, + pod: str, start_time: Optional[int] = None, end_time: Optional[int] = None, - newest_first: bool = False, - chunk_size: int = DEFAULT_LOG_PAGE_LINES, + chunk_size: int = 10, ) -> Iterator[List[DeploymentLogEvent]]: - """Fetch a revision's stored log lines within [start_time, end_time] (epoch - ms, inclusive; omit either bound to leave that side unbounded), yielded - lazily as chunks of 1..chunk_size DeploymentLogEvent — every chunk except - possibly the last holds exactly chunk_size — each stored line at most once, - each event carrying its pod name. - - newest_first selects only the order chunks arrive: False (the default) - walks the window oldest chunk first, True newest chunk first. Lines inside - every chunk are always in ascending (timestamp, id) order regardless of - direction. The defaults read the full retained history to the present; - newest_first=True with no bounds tails backward from the newest stored - line; start_time alone catches up from a known point to the present. - - Exhaustion is the only termination signal: the iterator ends once the - window is delivered, and one that yields nothing means the window holds no - stored lines (aged out of retention, before the deployment existed, an - unknown or not-yet-logging pod, or genuinely empty). There is no follow - mode; tailing is a caller loop of forward fetch_logs calls with - overlapping windows, deduplicated by event.id across calls (the README - documents a memory-bounded recipe — cross-call dedup is the caller's job). - - pod=None merges every pod of the revision into one stream; pass a name - from get_deployment_pods() to read a single pod. Nothing is fetched before - the first next(), and memory stays bounded however large the window: per - pod, at most LOG_MERGE_BUFFER_PAGES fetched pages wait in the merge and - the forward dedup anchor is trimmed to the server's re-delivery span. - - Ordering caveats. Forward: a line the log store received late (within its - ~15s re-delivery span) lands in a later chunk than its timestamp position — - never duplicated, but out of order across chunks; sort by event.id where - strict order matters. Backward: each time region is visited once, so a - line arriving late for a region already passed is absent from that call — - everything older than roughly the read's start minus the ingest lag is - complete; when completeness of the newest lines matters, read forward. - A single millisecond holding more than 5000 lines cannot be delivered - whole: a page carries the 5000 nearest its paging direction, so a forward - read retrieves at most 10000 of it and the middle is unreachable. + """Fetch one pod's stored log lines within [start_time, end_time] (epoch ms, + inclusive), yielded lazily oldest first as chunks of at most chunk_size + DeploymentLogEvent, each stored line at most once. Discover pod names with + get_deployment_pods(). + + start_time defaults to the current time, resolved once when fetch_logs is + called (not at the first next()), so lines logged while the generator sits + unstarted are not skipped; pass an earlier start_time to read history. + + With end_time set the iterator terminates once the window is delivered: + every chunk except possibly the last holds exactly chunk_size lines. + Without end_time it never terminates — once caught up it flushes any + partial chunk, then yields an empty chunk each time nothing new is stored + yet, and the caller decides when to sleep or break: + + for chunk in cclient.fetch_logs(dep, rev, pod): + if not chunk: + time.sleep(2) + continue + ... + + Nothing is fetched before the first next(), and memory stays bounded + however long the stream: the dedup anchor is trimmed to the server's ~15s + re-delivery span, so no line is delivered twice — across empty chunks too. + A line the log store received late lands in a later chunk than its + timestamp position, never duplicated; lines inside each chunk are always + in ascending (timestamp, id) order. """ if chunk_size < 1: raise ValueError("chunk_size must be a positive number of lines") @@ -501,116 +406,60 @@ def fetch_logs( raise ValueError("start_time and end_time are epoch milliseconds and must not be negative") if start_time is not None and end_time is not None and start_time > end_time: raise ValueError("start_time must not exceed end_time") - return self._iter_log_chunks( - deployment_id, revision_number, pod, start_time, end_time, newest_first, chunk_size - ) - - # pylint: disable=R0917 - def _iter_log_chunks( - self, - deployment_id: int, - revision_number: int, - pod: Optional[str], - start_time: Optional[int], - end_time: Optional[int], - newest_first: bool, - chunk_size: int, - ) -> Iterator[List[DeploymentLogEvent]]: - """The generator behind fetch_logs, split out so fetch_logs raises its - ValueErrors at the call site rather than at the first next().""" - - def pod_pages(name: str) -> Iterator[List[DeploymentLogEvent]]: - if newest_first: - return self._iter_pod_log_pages_backward(deployment_id, revision_number, name, start_time, end_time) - return self._iter_pod_log_pages( - deployment_id, revision_number, name, start_time if start_time is not None else 0, end_time - ) + start_ms = int(time.time() * 1000) if start_time is None else start_time - if pod is not None: - batches: Iterator[List[DeploymentLogEvent]] = pod_pages(pod) - else: - pods = self.get_deployment_pods(deployment_id, revision_number) - streams = {name: _PodLogStream(pages=pod_pages(name)) for name in pods} - batches = self._merge_pod_streams(streams, newest_first) - - pending: List[DeploymentLogEvent] = [] - for batch in batches: - if newest_first: - # Each batch is entirely older than everything pending, so prepending - # keeps pending ascending while chunks are cut from its newest end. - pending[:0] = batch - while len(pending) >= chunk_size: - yield pending[-chunk_size:] - del pending[-chunk_size:] - else: - for event in batch: + def chunks() -> Iterator[List[DeploymentLogEvent]]: + held: list = [] + pending: List[DeploymentLogEvent] = [] + # after is exclusive, so start_ms - 1 admits lines at start_ms itself. + initial_boundary = max(start_ms - 1, 0) + while True: + anchor: Union[list, int] = _recent_anchor(held) if held else initial_boundary + page = self._fetch_log_page( + deployment_id, revision_number, pod, after=anchor, max_lines=MAX_LOG_PAGE_LINES + ) + past_end = False + for raw in page: + if held and raw.id <= held[-1].id: + # Late arrival inside the look-behind span: keep the held window + # id-ordered (id order == time order) so trimming stays correct. + insort(held, raw, key=lambda held_event: held_event.id) + else: + held.append(raw) + # Anchoring at start_ms - 1 re-delivers the look-behind span below + # start_ms; those ids must be held for dedup but never emitted. + if raw.timestamp < start_ms: + continue + if end_time is not None and raw.timestamp > end_time: + past_end = True + continue + event = DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod) # A late arrival re-delivered inside the look-behind span can sort # below lines already pending; insort keeps every chunk ascending. if pending and (event.timestamp, event.id) < (pending[-1].timestamp, pending[-1].id): insort(pending, event, key=lambda pending_event: (pending_event.timestamp, pending_event.id)) else: pending.append(event) + if held: + held = _recent_anchor(held) while len(pending) >= chunk_size: yield pending[:chunk_size] del pending[:chunk_size] - if pending: - yield pending - - def _merge_pod_streams( - self, streams: Dict[str, _PodLogStream], newest_first: bool - ) -> Iterator[List[DeploymentLogEvent]]: - """Merge per-pod page iterators into (timestamp, id)-ascending batches that - arrive oldest-first (or newest-first) across batches. - - Strict cross-pod order while any pod is still fetching: reading forward, - release only lines at or below the least-advanced pod's frontier (its newest - buffered timestamp); a lagging pod's buffered lines are all at or below its - own frontier, so the minimum-frontier pod drains fully every round and the - merge cannot deadlock. Reading backward the roles mirror: a pod's frontier - is its oldest buffered timestamp, the watermark is the maximum frontier, and - lines at or above it are released — the maximum-frontier pod drains fully.""" - buffer_limit = LOG_MERGE_BUFFER_PAGES * MAX_LOG_PAGE_LINES - while True: - for stream in streams.values(): - if stream.exhausted or len(stream.buffer) >= buffer_limit: - continue # backpressure: let the merge watermark catch up before fetching more - page = next(stream.pages, None) - if page is None: - stream.exhausted = True - continue - if newest_first: - # Backward pages are entirely older than everything buffered. - stream.buffer[:0] = page - stream.frontier = stream.buffer[0].timestamp - else: - for event in page: - if stream.buffer and event.id <= stream.buffer[-1].id: - insort(stream.buffer, event, key=lambda buffered_event: buffered_event.id) - else: - stream.buffer.append(event) - stream.frontier = stream.buffer[-1].timestamp - - active = [stream.frontier for stream in streams.values() if not stream.exhausted] - watermark = (max(active) if newest_first else min(active)) if active else None - ready: List[DeploymentLogEvent] = [] - for stream in streams.values(): - if newest_first: - cut = len(stream.buffer) - while cut > 0 and (watermark is None or stream.buffer[cut - 1].timestamp >= watermark): - cut -= 1 - ready += stream.buffer[cut:] - del stream.buffer[cut:] - else: - cut = 0 - while cut < len(stream.buffer) and (watermark is None or stream.buffer[cut].timestamp <= watermark): - cut += 1 - ready += stream.buffer[:cut] - del stream.buffer[:cut] - ready.sort(key=lambda event: (event.timestamp, event.id)) - if ready: - yield ready - if watermark is None: - return + if past_end or (not page and end_time is not None): + break + if not page: + # Caught up with no end bound: flush the partial chunk, then + # signal "nothing new yet" until new lines are stored. + if pending: + yield pending[:] + pending.clear() + yield [] + if pending: + yield pending + + # The nested generator closes over the validated arguments, so the + # ValueErrors above raise at the call rather than at the first next(). + return chunks() @deprecated("deployment_log_session() is deprecated; use fetch_logs() instead") def deployment_log_session( diff --git a/tests/pytest.ini b/tests/pytest.ini index af211bd..bbeb447 100644 --- a/tests/pytest.ini +++ b/tests/pytest.ini @@ -4,7 +4,6 @@ env = CENTML_CACHE_DIR=/tmp/centml-test filterwarnings = ignore::UserWarning - ignore:.*use (CentMLClient.)?fetch_logs.. instead:DeprecationWarning markers = gpu: this test needs the gpu to run quickly diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 37cb9b5..54f23df 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -14,14 +14,7 @@ ) from centml.sdk import ApiException -from centml.sdk.api import ( - LOG_DEDUP_RETENTION_MS, - LOG_MERGE_BUFFER_PAGES, - MAX_LOG_PAGE_LINES, - CentMLClient, - DeploymentLogSession, - get_centml_client, -) +from centml.sdk.api import LOG_DEDUP_RETENTION_MS, CentMLClient, DeploymentLogSession, get_centml_client from centml.sdk.config import settings @@ -278,7 +271,8 @@ def test_get_deployment_logs_returns_tail_page_when_unanchored(): ) client = CentMLClient(api) - events = client.get_deployment_logs(123, 2, pod="pod-a") + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs(123, 2, pod="pod-a") assert [e.id for e in events] == ["1-a", "2-b"] api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once_with( @@ -292,7 +286,8 @@ def test_get_deployment_logs_before_pages_older_from_oldest_anchor(): client = CentMLClient(api) held = [_log_event("2-b", 2000), _log_event("3-c", 3000)] - events = client.get_deployment_logs(123, 2, pod="pod-a", before=held) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs(123, 2, pod="pod-a", before=held) assert [e.id for e in events] == ["1-a"] call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args @@ -306,7 +301,8 @@ def test_get_deployment_logs_before_empty_page_signals_beginning_of_history(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() client = CentMLClient(api) - assert client.get_deployment_logs(123, 2, pod="pod-a", before=[_log_event("1-a", 1000)]) == [] + with pytest.warns(DeprecationWarning): + assert client.get_deployment_logs(123, 2, pod="pod-a", before=[_log_event("1-a", 1000)]) == [] def test_get_deployment_logs_after_fetches_newer_from_newest_anchor(): @@ -315,7 +311,8 @@ def test_get_deployment_logs_after_fetches_newer_from_newest_anchor(): client = CentMLClient(api) held = [_log_event("1-a", 1000), _log_event("2-b", 2000)] - events = client.get_deployment_logs(123, 2, pod="pod-a", after=held) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs(123, 2, pod="pod-a", after=held) assert [e.id for e in events] == ["3-c"] call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args @@ -332,7 +329,8 @@ def test_get_deployment_logs_after_drops_redelivered_lines_but_keeps_late_arriva client = CentMLClient(api) held = [_log_event("1-a", 1000), _log_event("2-b", 2000)] - events = client.get_deployment_logs(123, 2, pod="pod-a", after=held) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs(123, 2, pod="pod-a", after=held) assert [e.id for e in events] == ["15-l", "3-c"] @@ -342,7 +340,8 @@ def test_get_deployment_logs_zero_after_anchor_reads_from_head(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page(_log_event("1-a", 1000)) client = CentMLClient(api) - events = client.get_deployment_logs(123, 2, pod="pod-a", after=0) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs(123, 2, pod="pod-a", after=0) assert [e.id for e in events] == ["1-a"] call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args @@ -355,7 +354,7 @@ def test_get_deployment_logs_rejects_empty_anchor_lists(): client = CentMLClient(api) for kwargs in ({"before": []}, {"after": []}): - with pytest.raises(ValueError): + with pytest.warns(DeprecationWarning), pytest.raises(ValueError): client.get_deployment_logs(123, 2, pod="pod-a", **kwargs) api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() @@ -366,7 +365,8 @@ def test_get_deployment_logs_after_empty_page_signals_nothing_new(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() client = CentMLClient(api) - assert client.get_deployment_logs(123, 2, pod="pod-a", after=[_log_event("1-a", 1000)]) == [] + with pytest.warns(DeprecationWarning): + assert client.get_deployment_logs(123, 2, pod="pod-a", after=[_log_event("1-a", 1000)]) == [] def test_get_deployment_logs_passes_max_lines_through(): @@ -374,7 +374,8 @@ def test_get_deployment_logs_passes_max_lines_through(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() client = CentMLClient(api) - client.get_deployment_logs(123, 2, pod="pod-a", max_lines=7) + with pytest.warns(DeprecationWarning): + client.get_deployment_logs(123, 2, pod="pod-a", max_lines=7) call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args assert call.kwargs["max_lines"] == 7 @@ -384,14 +385,15 @@ def test_get_deployment_logs_rejects_before_and_after_together(): api = MagicMock() client = CentMLClient(api) - with pytest.raises(ValueError): + with pytest.warns(DeprecationWarning), pytest.raises(ValueError): client.get_deployment_logs(123, 2, pod="pod-a", before=[_log_event("1-a", 1000)], after=0) api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() def _session(api, events=None): - return CentMLClient(api).deployment_log_session(123, 2, "pod-a", events=events) + with pytest.warns(DeprecationWarning): + return CentMLClient(api).deployment_log_session(123, 2, "pod-a", events=events) def test_log_session_first_fetch_is_tail_for_both_directions(): @@ -501,12 +503,14 @@ def test_get_deployment_logs_accepts_timestamp_anchors(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page(_log_event("2-b", 2000)) client = CentMLClient(api) - events = client.get_deployment_logs(123, 2, pod="pod-a", after=1999) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs(123, 2, pod="pod-a", after=1999) assert [e.id for e in events] == ["2-b"] call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args assert call.kwargs["fetch_newer"] is True and call.kwargs["timestamp"] == 1999 - client.get_deployment_logs(123, 2, pod="pod-a", before=5000) + with pytest.warns(DeprecationWarning): + client.get_deployment_logs(123, 2, pod="pod-a", before=5000) call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args assert call.kwargs["fetch_newer"] is False and call.kwargs["timestamp"] == 5000 @@ -520,7 +524,8 @@ def test_get_deployment_logs_range_trims_to_window(): ] client = CentMLClient(api) - events = client.get_deployment_logs_range(123, 2, pod="pod-a", start_time=1000, end_time=3000) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs_range(123, 2, pod="pod-a", start_time=1000, end_time=3000) assert [(e.id, e.pod) for e in events] == [("1-a", "pod-a"), ("2-b", "pod-a"), ("3-c", "pod-a")] calls = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list @@ -538,7 +543,8 @@ def test_get_deployment_logs_range_open_ended_reads_full_history(): ] client = CentMLClient(api) - events = client.get_deployment_logs_range(123, 2, pod="pod-a") + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs_range(123, 2, pod="pod-a") assert [e.id for e in events] == ["1-a", "2-b"] calls = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list @@ -561,7 +567,8 @@ def pages(**kwargs): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages client = CentMLClient(api) - events = client.get_deployment_logs_range(123, 2) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs_range(123, 2) assert [(e.id, e.pod, e.message) for e in events] == [ ("1-a", "pod-a", "line"), @@ -576,7 +583,8 @@ def test_get_deployment_logs_range_returns_empty_when_no_pod_has_logged(): api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace(pods=[]) client = CentMLClient(api) - assert client.get_deployment_logs_range(123, 2) == [] + with pytest.warns(DeprecationWarning): + assert client.get_deployment_logs_range(123, 2) == [] api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() @@ -589,7 +597,8 @@ def test_get_deployment_logs_range_single_millisecond_window(): ] client = CentMLClient(api) - events = client.get_deployment_logs_range(123, 2, pod="pod-a", start_time=2000, end_time=2000) + with pytest.warns(DeprecationWarning): + events = client.get_deployment_logs_range(123, 2, pod="pod-a", start_time=2000, end_time=2000) assert [e.id for e in events] == ["2-b"] calls = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list @@ -600,7 +609,7 @@ def test_get_deployment_logs_range_rejects_inverted_window(): api = MagicMock() client = CentMLClient(api) - with pytest.raises(ValueError): + with pytest.warns(DeprecationWarning), pytest.raises(ValueError): client.get_deployment_logs_range(123, 2, pod="pod-a", start_time=2000, end_time=1000) api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() @@ -647,6 +656,22 @@ def _flatten(chunks): return [event for chunk in chunks for event in chunk] +def _replaying_log_server(all_events, look_behind_ms=15_000, page_cap=None): + """Mimic the server's fetch-newer contract: newer-than-boundary lines up to + max_lines, plus the re-delivered look-behind span at and before the boundary + (uncounted). page_cap simulates a server that fills pages with fewer lines + than asked.""" + + def respond(**kwargs): + limit = min(kwargs["max_lines"], page_cap or kwargs["max_lines"]) + boundary = kwargs["timestamp"] + newer = [e for e in all_events if e.timestamp > boundary][:limit] + gray = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] + return _log_page(*sorted(gray + newer, key=lambda e: e.id)) + + return respond + + def test_fetch_logs_yields_first_chunk_before_fetching_the_next_page(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ @@ -656,7 +681,7 @@ def test_fetch_logs_yields_first_chunk_before_fetching_the_next_page(): ] client = CentMLClient(api) - stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=2) + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=2) first = next(stream) assert [(e.id, e.pod) for e in first] == [("1-a", "pod-a"), ("2-b", "pod-a")] @@ -678,24 +703,40 @@ def test_fetch_logs_chunk_size_shapes_the_yields(): ] client = CentMLClient(api) - chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=3)) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=3)) assert [len(chunk) for chunk in chunks] == [3, 3, 1] assert [e.id for e in _flatten(chunks)] == [f"{1000 + i}-x" for i in range(7)] -def test_fetch_logs_defaults_read_full_retained_history_oldest_first(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 6)] +def test_fetch_logs_bounded_chunks_are_full_except_the_last(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 12)] api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( + all_events, page_cap=4 + ) client = CentMLClient(api) - events = _flatten(client.fetch_logs(123, 2, pod="pod-a")) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=20_000, chunk_size=3)) + + assert [len(chunk) for chunk in chunks] == [3, 3, 3, 2] + for chunk in chunks: + assert [(e.timestamp, e.id) for e in chunk] == sorted((e.timestamp, e.id) for e in chunk) - assert [e.id for e in events] == [e.id for e in all_events] - # An unbounded start scans forward from the head of the retained window. - first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] - assert first_call.kwargs["fetch_newer"] is True and first_call.kwargs["timestamp"] == 0 + +def test_fetch_logs_start_time_defaults_to_now_resolved_at_the_call(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() + client = CentMLClient(api) + + with patch("centml.sdk.api.time.time", return_value=5000.0): + stream = client.fetch_logs(123, 2, pod="pod-a") + # "now" is pinned at the call, not the first next(): iterating under a later + # clock still anchors just below the call-time millisecond (after is exclusive). + with patch("centml.sdk.api.time.time", return_value=9000.0): + assert next(stream) == [] + call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args + assert call.kwargs["fetch_newer"] is True and call.kwargs["timestamp"] == 5_000_000 - 1 def test_fetch_logs_end_time_truncates_the_window_and_stops_fetching(): @@ -713,7 +754,7 @@ def test_fetch_logs_end_time_truncates_the_window_and_stops_fetching(): assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 1 -def test_fetch_logs_terminates_when_caught_up(): +def test_fetch_logs_bounded_read_terminates_when_caught_up(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ _log_page(_log_event("1-a", 1000)), @@ -721,37 +762,43 @@ def test_fetch_logs_terminates_when_caught_up(): ] client = CentMLClient(api) - events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1)) + # end_time still in the future: an empty page means the store is caught up, + # and with an end bound set that terminates the read. + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) assert [e.id for e in events] == ["1-a"] assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 2 -def _replaying_log_server(all_events, look_behind_ms=15_000, page_cap=None): - """Mimic the server for both directions. fetch_newer: newer-than-boundary lines - up to max_lines, plus the re-delivered look-behind span at and before the - boundary (uncounted). Otherwise: the newest max_lines strictly older than the - boundary (no look-behind), or the tail page when the boundary is None. - page_cap simulates a server that fills pages with fewer lines than asked.""" +def test_fetch_logs_open_ended_yields_empty_chunks_and_resumes_without_duplicates(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), + _log_page(), # caught up: flush the partial chunk, then "nothing new yet" + _log_page(), # still nothing + _log_page(_log_event("2-b", 2000), _log_event("3-c", 3000)), # look-behind re-delivers 2-b + _log_page(), + ] + client = CentMLClient(api) - def respond(**kwargs): - limit = min(kwargs["max_lines"], page_cap or kwargs["max_lines"]) - boundary = kwargs["timestamp"] - if kwargs["fetch_newer"]: - newer = [e for e in all_events if e.timestamp > boundary][:limit] - gray = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] - return _log_page(*sorted(gray + newer, key=lambda e: e.id)) - older = all_events if boundary is None else [e for e in all_events if e.timestamp < boundary] - return _log_page(*older[-limit:]) + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1) - return respond + # Without end_time the generator never returns: an empty chunk is the + # "nothing new yet" signal and the caller decides when to sleep or break. + assert [e.id for e in next(stream)] == ["1-a", "2-b"] + assert next(stream) == [] + assert next(stream) == [] + # It resumes delivering once new lines are stored, and the line re-delivered + # inside the look-behind span never crosses the empty-chunk boundary twice. + assert [e.id for e in next(stream)] == ["3-c"] + assert next(stream) == [] def test_fetch_logs_does_not_livelock_on_gray_span_redelivery(): # Regression: with a bare int boundary the re-delivered look-behind span keeps # every page non-empty forever (measured against dev: 9 iterations of the same - # 7 gray lines before the naive port was declared wedged). The window iterator - # holds the trailing events, so the gray span dedupes away and the read terminates. + # 7 gray lines before the naive port was declared wedged). The held anchor + # dedupes the gray span away, so the bounded read terminates. all_events = [_log_event(f"{1000 + i:05d}-x", 1000 + i) for i in range(30)] api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( @@ -759,7 +806,7 @@ def test_fetch_logs_does_not_livelock_on_gray_span_redelivery(): ) client = CentMLClient(api) - events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1)) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=100_000)) assert [e.id for e in events] == [e.id for e in all_events] # every line once, in order # 3 data pages + 1 empty page proving catch-up; a livelock would exceed this. @@ -777,7 +824,7 @@ def test_fetch_logs_start_time_holds_gray_lines_below_the_window(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) client = CentMLClient(api) - events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=5000)) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=5000, end_time=100_000)) # The look-behind lines below start_time are held for dedup but never emitted. assert [e.id for e in events] == ["05000-y", "06000-z"] @@ -804,84 +851,38 @@ def spying_fetch_log_page(self, *args, **kwargs): return original(self, *args, **kwargs) with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): - events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1)) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10**12)) assert len(events) == 4900 # Held state is the trimmed dedup window, not the accumulated stream. assert max(anchor_sizes) <= LOG_DEDUP_RETENTION_MS // step_ms + 1 -def test_fetch_logs_merges_pods_by_timestamp_then_id(): - api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a", "pod-b"] - ) - - def pages(**kwargs): - if kwargs["timestamp"]: - return _log_page() - if kwargs["pod"] == "pod-a": - return _log_page(_log_event("1-a", 1000), _log_event("3-a", 3000)) - return _log_page(_log_event("2-b", 2000), _log_event("4-b", 4000)) - - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages - client = CentMLClient(api) - - events = _flatten(client.fetch_logs(123, 2, start_time=1)) - - assert [(e.id, e.pod) for e in events] == [("1-a", "pod-a"), ("2-b", "pod-b"), ("3-a", "pod-a"), ("4-b", "pod-b")] - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_called_once() - - -def test_fetch_logs_returns_empty_when_no_pod_has_logged(): +def test_fetch_logs_single_millisecond_window(): + all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 4)] api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace(pods=[]) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) client = CentMLClient(api) - assert not list(client.fetch_logs(123, 2, start_time=1)) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=2000, end_time=2000)) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() + assert [e.id for e in events] == ["02000-x"] -def test_fetch_logs_backpressures_a_pod_far_ahead_of_the_watermark(): - # A terminated old pod gates the watermark while a live pod's history is far newer; - # without backpressure every old-pod round would buffer another new-pod page, growing - # the merge buffer with the live pod's whole history. +def test_fetch_logs_late_arrival_lands_in_a_later_chunk_still_ascending(): api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-old", "pod-new"] - ) - old_count, new_count = 3 * MAX_LOG_PAGE_LINES, 5 * MAX_LOG_PAGE_LINES - events = { - "pod-old": [_log_event(f"old-{i:07d}", 1_000_000 + i) for i in range(old_count)], - "pod-new": [_log_event(f"new-{i:07d}", 100_000_000 + i) for i in range(new_count)], - } - - def pages(**kwargs): - newer = [e for e in events[kwargs["pod"]] if e.timestamp > kwargs["timestamp"]] - return _log_page(*newer[: kwargs["max_lines"]]) - - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("01000-a", 1000), _log_event("02000-b", 2000), _log_event("03000-c", 3000)), + # A late arrival re-delivered inside the look-behind span sorts below the + # pending line 03000-c; every chunk must still be internally ascending. + _log_page(_log_event("02500-l", 2500), _log_event("04000-d", 4000)), + _log_page(), + ] client = CentMLClient(api) - calls = {"pod-old": 0, "pod-new": 0} - new_calls_while_old_active = [0] - original = CentMLClient._fetch_log_page - - def spying_fetch_log_page(self, *args, **kwargs): - calls[args[2]] += 1 - if args[2] == "pod-old": - new_calls_while_old_active[0] = calls["pod-new"] - return original(self, *args, **kwargs) - - with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): - yielded = _flatten(client.fetch_logs(123, 2, start_time=1, chunk_size=MAX_LOG_PAGE_LINES)) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=2)) - assert [e.id for e in yielded] == [e.id for e in events["pod-old"]] + [e.id for e in events["pod-new"]] - # While the old pod was still draining, the new pod was fetched at most its buffer - # cap (LOG_MERGE_BUFFER_PAGES pages), not once per round. - assert new_calls_while_old_active[0] <= LOG_MERGE_BUFFER_PAGES - assert calls["pod-new"] == new_count // MAX_LOG_PAGE_LINES + 1 # data pages + 1 empty, none wasted + assert [[e.id for e in chunk] for chunk in chunks] == [["01000-a", "02000-b"], ["02500-l", "03000-c"], ["04000-d"]] def test_fetch_logs_validates_eagerly_at_the_call_not_the_first_next(): @@ -899,20 +900,31 @@ def test_fetch_logs_validates_eagerly_at_the_call_not_the_first_next(): def test_fetch_logs_is_lazy_until_the_first_next(): api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a"] - ) api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page(_log_event("1-a", 1000)) client = CentMLClient(api) - stream = client.fetch_logs(123, 2) + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=1) - # Nothing — not even pod discovery — is fetched before the first next(). - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_not_called() + # Nothing is fetched before the first next(). api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() next(stream) - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.assert_called_once() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once() + + +def test_fetch_logs_does_not_warn_on_its_own_internal_calls(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000)), + _log_page(), + ] + client = CentMLClient(api) + + with warnings.catch_warnings(): + warnings.simplefilter("error", DeprecationWarning) + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) + + assert len(events) == 1 def test_deprecated_log_readers_warn_and_name_the_replacement(): @@ -938,306 +950,3 @@ def test_deprecated_log_readers_warn_and_name_the_replacement(): with warnings.catch_warnings(): warnings.simplefilter("error", DeprecationWarning) assert session.fetch_older() == [] - - -def test_fetch_logs_does_not_warn_on_its_own_internal_calls(): - api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a", "pod-b"] - ) - - def pages(**kwargs): - if kwargs["timestamp"]: - return _log_page() - return _log_page(_log_event(f"1-{kwargs['pod']}", 1000)) - - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = pages - client = CentMLClient(api) - - with warnings.catch_warnings(): - warnings.simplefilter("error", DeprecationWarning) - events = _flatten(client.fetch_logs(123, 2, start_time=1)) - - assert len(events) == 2 - - -def _multi_pod_log_server(events_by_pod, **server_kwargs): - responders = {pod: _replaying_log_server(events, **server_kwargs) for pod, events in events_by_pod.items()} - - def respond(**kwargs): - return responders[kwargs["pod"]](**kwargs) - - return respond - - -def test_fetch_logs_newest_first_unbounded_walks_back_to_history_start(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 8)] - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events, page_cap=3 - ) - client = CentMLClient(api) - - chunks = list(client.fetch_logs(123, 2, pod="pod-a", newest_first=True, chunk_size=3)) - - # Chunks walk toward older times; lines inside every chunk stay ascending. - assert [[e.id for e in chunk] for chunk in chunks] == [ - ["05000-x", "06000-x", "07000-x"], - ["02000-x", "03000-x", "04000-x"], - ["01000-x"], - ] - # An unbounded end starts at the tail page: no boundary at all. - first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] - assert first_call.kwargs["fetch_newer"] is False and first_call.kwargs["timestamp"] is None - - -def test_fetch_logs_newest_first_stops_at_start_time(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 9)] - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events, page_cap=3 - ) - client = CentMLClient(api) - - chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=3000, newest_first=True, chunk_size=3)) - - assert [e.id for e in _flatten(chunks)] == ["06000-x", "07000-x", "08000-x", "03000-x", "04000-x", "05000-x"] - # The page that crossed below start_time already proves the window is complete. - assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 3 - - -def test_fetch_logs_newest_first_end_time_bounds_the_first_page(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 9)] - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server(all_events) - client = CentMLClient(api) - - events = _flatten(client.fetch_logs(123, 2, pod="pod-a", end_time=5000, newest_first=True)) - - assert [e.id for e in events] == [f"{1000 * i:05d}-x" for i in range(1, 6)] - # before is exclusive: end_time + 1 admits lines at end_time itself. - first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] - assert first_call.kwargs["fetch_newer"] is False and first_call.kwargs["timestamp"] == 5001 - - -def test_fetch_logs_newest_first_bounded_window_walks_end_to_start(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 9)] - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events, page_cap=2 - ) - client = CentMLClient(api) - - chunks = list( - client.fetch_logs(123, 2, pod="pod-a", start_time=2000, end_time=6000, newest_first=True, chunk_size=2) - ) - - assert [[e.id for e in chunk] for chunk in chunks] == [["05000-x", "06000-x"], ["03000-x", "04000-x"], ["02000-x"]] - - -def test_fetch_logs_single_millisecond_window_in_both_directions(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 4)] - for newest_first in (False, True): - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events - ) - client = CentMLClient(api) - - events = _flatten( - client.fetch_logs(123, 2, pod="pod-a", start_time=2000, end_time=2000, newest_first=newest_first) - ) - - assert [e.id for e in events] == ["02000-x"] - - -def test_fetch_logs_chunks_never_exceed_chunk_size_and_only_the_last_is_partial(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 12)] - for newest_first in (False, True): - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events, page_cap=4 - ) - client = CentMLClient(api) - - chunks = list(client.fetch_logs(123, 2, pod="pod-a", newest_first=newest_first, chunk_size=3)) - - assert [len(chunk) for chunk in chunks] == [3, 3, 3, 2] - assert all(chunk for chunk in chunks) - for chunk in chunks: - assert [(e.timestamp, e.id) for e in chunk] == sorted((e.timestamp, e.id) for e in chunk) - - -def test_fetch_logs_forward_late_arrival_lands_in_a_later_chunk_still_ascending(): - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ - _log_page(_log_event("01000-a", 1000), _log_event("02000-b", 2000), _log_event("03000-c", 3000)), - # A late arrival re-delivered inside the look-behind span sorts below the - # pending line 03000-c; every chunk must still be internally ascending. - _log_page(_log_event("02500-l", 2500), _log_event("04000-d", 4000)), - _log_page(), - ] - client = CentMLClient(api) - - chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, chunk_size=2)) - - assert [[e.id for e in chunk] for chunk in chunks] == [["01000-a", "02000-b"], ["02500-l", "03000-c"], ["04000-d"]] - - -def test_fetch_logs_newest_first_uses_no_dedup_anchors_and_delivers_each_line_once(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 30)] - api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events, page_cap=7 - ) - client = CentMLClient(api) - - anchors = [] - original = CentMLClient._fetch_log_page - - def spying_fetch_log_page(self, *args, **kwargs): - anchors.append((kwargs.get("before"), kwargs.get("after"))) - return original(self, *args, **kwargs) - - with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): - events = _flatten(client.fetch_logs(123, 2, pod="pod-a", newest_first=True)) - - delivered = [e.id for e in events] - assert sorted(delivered) == [e.id for e in all_events] - assert len(delivered) == len(set(delivered)) - # A backward read never carries dedup state: every boundary is a bare int (or - # None for the tail page) and the after anchor is never used. - assert all(after is None and (before is None or isinstance(before, int)) for before, after in anchors) - - -def test_fetch_logs_newest_first_merges_pods_newest_chunk_first(): - api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a", "pod-b"] - ) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _multi_pod_log_server( - { - "pod-a": [_log_event(f"{ts:05d}-a", ts) for ts in (1000, 3000, 5000)], - "pod-b": [_log_event(f"{ts:05d}-b", ts) for ts in (2000, 4000, 6000)], - } - ) - client = CentMLClient(api) - - chunks = list(client.fetch_logs(123, 2, newest_first=True, chunk_size=2)) - - assert [[(e.id, e.pod) for e in chunk] for chunk in chunks] == [ - [("05000-a", "pod-a"), ("06000-b", "pod-b")], - [("03000-a", "pod-a"), ("04000-b", "pod-b")], - [("01000-a", "pod-a"), ("02000-b", "pod-b")], - ] - - -def test_fetch_logs_newest_first_interleaved_pods_deliver_every_line_once_in_order(): - # Backward-merge deadlock probe: interleaved pods, small pages, many rounds. - events_by_pod = { - "pod-a": [_log_event(f"{ts:06d}-a", ts) for ts in range(1000, 100_000, 210)], - "pod-b": [_log_event(f"{ts:06d}-b", ts) for ts in range(1100, 100_000, 350)], - } - api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-a", "pod-b"] - ) - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _multi_pod_log_server( - events_by_pod, page_cap=13 - ) - client = CentMLClient(api) - - chunks = list(client.fetch_logs(123, 2, newest_first=True, chunk_size=17)) - - flattened = _flatten(chunks) - expected = sorted((e for events in events_by_pod.values() for e in events), key=lambda e: (e.timestamp, e.id)) - # Every line exactly once; chunks internally ascending and strictly older across chunks. - assert sorted(e.id for e in flattened) == sorted(e.id for e in expected) - assert len(flattened) == len(expected) - previous_min = None - for chunk in chunks: - keys = [(e.timestamp, e.id) for e in chunk] - assert keys == sorted(keys) - if previous_min is not None: - assert keys[-1] < previous_min - previous_min = keys[0] - - -def test_fetch_logs_newest_first_backpressures_the_lagging_old_pod(): - # The backward mirror of the asymmetric layout: reading newest-first, the live - # pod with new timestamps gates the watermark while the terminated old pod's - # buffer would otherwise grow with its whole history. - api = MagicMock() - api.get_deployment_pods_deployments_pods_deployment_id_revision_number_get.return_value = SimpleNamespace( - pods=["pod-old", "pod-new"] - ) - old_count, new_count = 3 * MAX_LOG_PAGE_LINES, 5 * MAX_LOG_PAGE_LINES - events = { - "pod-old": [_log_event(f"old-{i:07d}", 1_000_000 + i) for i in range(old_count)], - "pod-new": [_log_event(f"new-{i:07d}", 100_000_000 + i) for i in range(new_count)], - } - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _multi_pod_log_server(events) - client = CentMLClient(api) - - calls = {"pod-old": 0, "pod-new": 0} - old_calls_while_new_active = [0] - original = CentMLClient._fetch_log_page - - def spying_fetch_log_page(self, *args, **kwargs): - calls[args[2]] += 1 - if args[2] == "pod-new": - old_calls_while_new_active[0] = calls["pod-old"] - return original(self, *args, **kwargs) - - with patch.object(CentMLClient, "_fetch_log_page", spying_fetch_log_page): - yielded = _flatten(client.fetch_logs(123, 2, newest_first=True, chunk_size=MAX_LOG_PAGE_LINES)) - - def backward_page_order(pod_events): - pages = [pod_events[i : i + MAX_LOG_PAGE_LINES] for i in range(0, len(pod_events), MAX_LOG_PAGE_LINES)] - return [e.id for page in reversed(pages) for e in page] - - assert [e.id for e in yielded] == backward_page_order(events["pod-new"]) + backward_page_order(events["pod-old"]) - # While the new pod was still draining, the old pod was fetched at most its - # buffer cap (LOG_MERGE_BUFFER_PAGES pages), not once per round. - assert old_calls_while_new_active[0] <= LOG_MERGE_BUFFER_PAGES - assert calls["pod-old"] == old_count // MAX_LOG_PAGE_LINES + 1 # data pages + 1 empty, none wasted - - -def test_documented_tail_recipe_is_duplicate_free_and_memory_bounded(): - # The README tail recipe: re-call fetch_logs with the next window starting - # OVERLAP_MS below the newest seen line, dedup by id across calls, and trim - # the id set to the overlap window so it never grows with the stream. - overlap_ms = 30_000 - base = 1_000_000 - all_events = [_log_event(f"{base + i * 100:09d}-x", base + i * 100) for i in range(200)] - visible = [100] # grow between polls to simulate a live stream - api = MagicMock() - - def respond(**kwargs): - return _replaying_log_server(all_events[: visible[0]])(**kwargs) - - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = respond - client = CentMLClient(api) - - delivered = [] - seen = {} - boundary = base # newest timestamp seen so far; the first window reads from base - peak_seen = 0 - for _ in range(4): - for chunk in client.fetch_logs( - 123, 2, pod="pod-a", start_time=max(boundary - overlap_ms, 0), newest_first=False - ): - for event in chunk: - if event.id in seen: - continue - seen[event.id] = event.timestamp - boundary = max(boundary, event.timestamp) - delivered.append(event.id) - cutoff = boundary - overlap_ms - seen = {event_id: ts for event_id, ts in seen.items() if ts >= cutoff} - peak_seen = max(peak_seen, len(seen)) - visible[0] = min(visible[0] + 50, len(all_events)) - - assert delivered == [e.id for e in all_events] # every line exactly once, in order - # The dedup state holds only the overlap window, not the whole stream. - assert peak_seen <= overlap_ms // 100 + 1 From 7588562b83d53f53dc00e0de32dece4a2ec19026 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 10:35:16 -0400 Subject: [PATCH 12/22] Trim log docs to one window read and one tail example The tail recipe with its seen dict, overlap paragraphs and the 0.5.x and 0.6.0 migration tables are gone; the example shows a window read and a tail loop over a single generator. Signed-off-by: Honglin Cao --- README.md | 134 ++++------------------------ examples/sdk/get_deployment_logs.py | 79 +++++++--------- 2 files changed, 49 insertions(+), 164 deletions(-) diff --git a/README.md b/README.md index 7d22e3a..e31da90 100644 --- a/README.md +++ b/README.md @@ -55,135 +55,39 @@ delete the deployment automatically. ### Deployment logs SDK example -`fetch_logs()` is the one way to read deployment logs: it fetches a revision's -stored log lines within a time window (`start_time`/`end_time`, epoch ms, -inclusive; omit either bound to leave that side unbounded) and yields them lazily -as chunks of up to `chunk_size` `DeploymentLogEvent` — each line at most once, -each event carrying its pod name, with bounded memory however large the window. -`newest_first` selects only the order chunks arrive: `False` (the default) walks -the window oldest chunk first, `True` newest chunk first; lines inside every chunk -are always in ascending `(timestamp, id)` order. So the bare call reads the full -retained history chronologically, `newest_first=True` starts from the newest -stored line and walks backward, and `start_time` alone catches up from a known -point to the present. By default every pod of the revision is merged into one -stream; pass `pod=` to read a single pod — discover names with -`get_deployment_pods()` (terminated pods still within log retention are included): +`fetch_logs()` is the one way to read deployment logs: it fetches one pod's stored +log lines within a time window (`start_time`/`end_time`, epoch ms, inclusive) and +yields them lazily, oldest first, as chunks of up to `chunk_size` +`DeploymentLogEvent` — each line at most once, with bounded memory however long +the stream. Discover pod names with `get_deployment_pods()` (terminated pods +still within log retention are included). `start_time` defaults to the moment of +the call; with `end_time` set the iterator terminates once the window is +delivered: ```python -for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, start_time=t1_ms, end_time=t2_ms): +for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod, start_time=t1_ms, end_time=t2_ms): for event in chunk: print(event.pod, event.message) ``` -The iterator always terminates, and its exhaustion is the only termination signal: -one that yields nothing means the window holds no stored lines (aged out of -retention, before the deployment existed, an unknown pod, or genuinely empty). -Reading backward, note that a line the log store receives late for a time region -the walk has already passed is absent from that call: everything older than -roughly the read's start minus the ingest lag (~15s) is complete, and when -completeness of the newest lines matters, read forward. There is no follow mode: -tailing is a caller loop that re-calls a forward `fetch_logs` with a later -`start_time` and deduplicates by `event.id`: +Without `end_time` the same generator tails: it never terminates, and once caught +up it yields an empty chunk each time nothing new is stored yet — the caller +decides when to sleep or break: ```python import time -OVERLAP_MS = 30_000 # covers the server's ~15s late-arrival re-delivery span -POLL_SECONDS = 2.0 - -seen = {} # event id -> timestamp, trimmed to the overlap window each round -boundary = int(time.time() * 1000) # newest timestamp seen so far -while True: - for chunk in cclient.fetch_logs( - DEPLOYMENT_ID, REVISION, start_time=max(boundary - OVERLAP_MS, 0), newest_first=False - ): - for event in chunk: - if event.id in seen: - continue - seen[event.id] = event.timestamp - boundary = max(boundary, event.timestamp) - print(event.pod, event.message) - cutoff = boundary - OVERLAP_MS - seen = {event_id: ts for event_id, ts in seen.items() if ts >= cutoff} - time.sleep(POLL_SECONDS) -``` - -Two properties of this loop matter. Consecutive windows overlap on purpose: the log -store may deliver a line up to ~15 seconds after its timestamp, so starting each call -`OVERLAP_MS` below the newest seen line is what keeps late arrivals from being -skipped — do not advance `start_time` past that span to avoid the duplicates. And the -dedup state is bounded: only ids inside the overlap window can come back again, so -`seen` is trimmed to that window each round and never grows with the stream. - -`python examples/sdk/get_deployment_logs.py` runs a newest-first peek, a full -chronological read and this tail loop. `get_deployment_logs()`, `get_deployment_logs_range()` and -`deployment_log_session()` still work but are deprecated in favor of `fetch_logs()` -and raise a `DeprecationWarning` on use. - -### Migrating deployment log reads from 0.5.x - -`get_deployment_logs()` kept its name but not its signature, and is now deprecated: -`start_time`, `end_time`, `line_count`, `start_from_head` and `stream` are gone, and -`fetch_logs()` is the replacement for every read. A 0.5.x call raises `TypeError` -(or a validation error, if its arguments were positional) rather than returning -something wrong, so no call site fails silently. - -| To | 0.5.x | now | -|---|---|---| -| Read a time window | `get_deployment_logs(id, rev, start_time=, end_time=)` | `fetch_logs(id, rev, start_time=, end_time=)` | -| Stream a window lazily | the same call with `stream=True` | `fetch_logs(...)` — chunks are yielded as they are fetched | -| Take the newest lines first | `start_from_head=False` | `fetch_logs(id, rev, newest_first=True)` | -| Read from the beginning | `start_from_head=True` | `fetch_logs(id, rev)` — oldest first is the default | -| Cap what one iteration hands you | `line_count=n` | `chunk_size=n` | -| Tell which pod a line came from | parse `kubernetes.pod_name` out of `message` | `event.pod` | -| Keep tailing past the window | not supported | re-call `fetch_logs` with overlapping windows (the tail loop above) | - -A whole-window read loses its envelope parsing, because `message` is now the log line -itself rather than a JSON record wrapping it: - -```python -# 0.5.x -events = cclient.get_deployment_logs(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2) -for event in events: - record = json.loads(event["message"]) - print(record["kubernetes"]["pod_name"], record["log"]) - -# now -for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2): +for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod): + if not chunk: + time.sleep(2) + continue for event in chunk: print(event.pod, event.message) ``` -A `stream=True` loop becomes a `fetch_logs()` loop, which yields each chunk as it -arrives just as the old generator yielded pages: - -```python -# 0.5.x -for event in cclient.get_deployment_logs( - DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2, stream=True -): - print(json.loads(event["message"])["log"]) - -# now -for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, start_time=t1, end_time=t2): - for event in chunk: - print(event.message) -``` - -One contract change to check error handling against: a revision that does not exist -now answers 404 where the old endpoint answered 400. - -The 0.6.0 readers — `get_deployment_logs()` page anchoring, `get_deployment_logs_range()` -and `deployment_log_session()` — still work but are deprecated and warn on use; the -look-behind anchoring they exposed is handled inside `fetch_logs()`: - -| 0.6.0 | now | -|---|---| -| `get_deployment_logs(id, rev, pod)` — newest page of one pod | `fetch_logs(id, rev, pod=pod, newest_first=True)` and take the first chunk | -| `get_deployment_logs(id, rev, pod, after=events)` — page newer than held events | `fetch_logs(id, rev, pod=pod, start_time=boundary_ms)` (the tail loop above for repeated polling) | -| `get_deployment_logs_range(id, rev, start_time=, end_time=)` | `fetch_logs(id, rev, start_time=, end_time=)` — chunked and lazy instead of one list | -| `deployment_log_session(...).fetch_older()` loop | `fetch_logs(id, rev, pod=pod, newest_first=True)` — one iterator walks back to the start | -| `session.fetch_newer()` polling | the tail loop above | +`python examples/sdk/get_deployment_logs.py` runs both. `get_deployment_logs()`, +`get_deployment_logs_range()` and `deployment_log_session()` still work but are +deprecated in favor of `fetch_logs()` and raise a `DeprecationWarning` on use. ### Un-installation diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index 9dafbbb..dcfcae0 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -6,9 +6,8 @@ # --- Configuration --- DEPLOYMENT_ID = 1234 # Replace with your deployment ID REVISION_NUMBER = 10 -RECENT_LINES = 20 # How many of the newest stored lines to peek at +WINDOW_MINUTES = 10 # How far back the window read looks TAIL_LINES = 20 # How many tailed lines to print before stopping the tail loop -OVERLAP_MS = 30_000 # Covers the server's ~15s late-arrival re-delivery span POLL_SECONDS = 2.0 @@ -19,58 +18,40 @@ def format_event(event) -> str: def main(): with get_centml_client() as cclient: - # The newest stored lines, without reading the whole history: newest_first - # walks the window backward, one chunk at a time. Direction changes only - # the order chunks arrive — lines inside each chunk are always ascending. - print(f"Newest {RECENT_LINES} lines of deployment {DEPLOYMENT_ID} revision {REVISION_NUMBER}:\n") - printed = 0 - for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION_NUMBER, newest_first=True, chunk_size=RECENT_LINES): + # Discover pod names; terminated pods still within log retention are included. + pods = cclient.get_deployment_pods(DEPLOYMENT_ID, REVISION_NUMBER) + pod = pods[0] + + # A window read: start_time/end_time are epoch ms, inclusive. With end_time + # set the iterator terminates once the window is delivered. fetch_logs is + # lazy — chunks are yielded as they are fetched, with bounded memory + # however large the window. + now_ms = int(time.time() * 1000) + print(f"Last {WINDOW_MINUTES} minutes of pod {pod}:\n") + count = 0 + for chunk in cclient.fetch_logs( + DEPLOYMENT_ID, REVISION_NUMBER, pod, start_time=now_ms - WINDOW_MINUTES * 60_000, end_time=now_ms + ): for event in chunk: print(format_event(event)) - printed += len(chunk) - if printed >= RECENT_LINES: - break - - # A full chronological read, all pods merged. fetch_logs is lazy — chunks - # are yielded as they are fetched, with bounded memory however large the - # window — and always terminates once caught up. Bound the window with - # start_time/end_time (epoch ms, inclusive) when the history is long. - count = 0 - for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION_NUMBER): count += len(chunk) - print(f"\nFull retained history holds {count} lines.") + print(f"\nThe window holds {count} lines.") - # Tailing is a caller loop: re-call a forward fetch_logs with the next - # window starting OVERLAP_MS below the newest seen line, so lines the log - # store delivers late (up to ~15s after their timestamp) are not skipped, - # and deduplicate by event.id. Only ids inside the overlap window can come - # back again, so trimming `seen` to it keeps the loop's memory bounded. - print(f"\nTailing; stopping after {TAIL_LINES} new lines...") - seen = {} # event id -> timestamp, trimmed to the overlap window each round - boundary = int(time.time() * 1000) # newest timestamp seen so far + # A tail: without end_time the same generator never terminates. start_time + # defaults to the moment of the call, and once caught up the generator + # yields an empty chunk each time nothing new is stored yet — the caller + # decides when to sleep or break. No line is ever delivered twice. + print(f"\nTailing pod {pod}; stopping after {TAIL_LINES} new lines...") printed = 0 - while printed < TAIL_LINES: - for chunk in cclient.fetch_logs( - DEPLOYMENT_ID, REVISION_NUMBER, start_time=max(boundary - OVERLAP_MS, 0), newest_first=False - ): - for event in chunk: - if event.id in seen: - continue - seen[event.id] = event.timestamp - boundary = max(boundary, event.timestamp) - print(format_event(event)) - printed += 1 - cutoff = boundary - OVERLAP_MS - seen = {event_id: ts for event_id, ts in seen.items() if ts >= cutoff} - time.sleep(POLL_SECONDS) - - # A single pod (discover names with get_deployment_pods; terminated pods - # still within log retention are included), with caller-sized chunks: - # pods = cclient.get_deployment_pods(DEPLOYMENT_ID, REVISION_NUMBER) - # for chunk in cclient.fetch_logs( - # DEPLOYMENT_ID, REVISION_NUMBER, pod=pods[0], start_time=t1_ms, end_time=t2_ms, chunk_size=500 - # ): - # ... + for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION_NUMBER, pod): + if not chunk: + time.sleep(POLL_SECONDS) + continue + for event in chunk: + print(format_event(event)) + printed += len(chunk) + if printed >= TAIL_LINES: + break if __name__ == "__main__": From 4510b25b93f2bfb2c1c2db42144e14db914a8503 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 11:58:38 -0400 Subject: [PATCH 13/22] Make chunk_size the server page size in fetch_logs Request the caller's chunk_size as max_lines instead of overriding it with MAX_LOG_PAGE_LINES, and yield each server page as one chunk rather than buffering pages to re-slice them into exact chunk_size pieces. A chunk can now be smaller (the first page's look-behind span below start_time and re-delivered lines are filtered out) or larger (the server never splits a millisecond, so a burst millisecond arrives whole). chunk_size goes on the wire, so it inherits the server's ceiling and is validated eagerly at the call. The within-chunk insort stays: the server sorts a page by nanosecond timestamp only, never by the id's hash suffix, so lines sharing one nanosecond can arrive in either id order (verified against local Loki). Signed-off-by: Honglin Cao --- README.md | 15 +++-- centml/sdk/api.py | 62 +++++++++++--------- examples/sdk/get_deployment_logs.py | 12 +++- tests/test_sdk_api.py | 90 ++++++++++++++++++++++------- 4 files changed, 122 insertions(+), 57 deletions(-) diff --git a/README.md b/README.md index e31da90..bbc99fd 100644 --- a/README.md +++ b/README.md @@ -57,12 +57,15 @@ delete the deployment automatically. `fetch_logs()` is the one way to read deployment logs: it fetches one pod's stored log lines within a time window (`start_time`/`end_time`, epoch ms, inclusive) and -yields them lazily, oldest first, as chunks of up to `chunk_size` -`DeploymentLogEvent` — each line at most once, with bounded memory however long -the stream. Discover pod names with `get_deployment_pods()` (terminated pods -still within log retention are included). `start_time` defaults to the moment of -the call; with `end_time` set the iterator terminates once the window is -delivered: +yields them lazily, oldest first, as chunks of `DeploymentLogEvent` — each line at +most once, with bounded memory however long the stream. `chunk_size` (1 to 5000) +is the number of lines requested from the server per round trip and each server +page becomes one chunk, so a bulk read of history wants a large `chunk_size` — +the log read path is rate-limited upstream, and a small `chunk_size` over a large +window multiplies requests. Discover pod names with `get_deployment_pods()` +(terminated pods still within log retention are included). `start_time` defaults +to the moment of the call; with `end_time` set the iterator terminates once the +window is delivered: ```python for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod, start_time=t1_ms, end_time=t2_ms): diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 0347ee2..b529650 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -373,19 +373,28 @@ def fetch_logs( chunk_size: int = 10, ) -> Iterator[List[DeploymentLogEvent]]: """Fetch one pod's stored log lines within [start_time, end_time] (epoch ms, - inclusive), yielded lazily oldest first as chunks of at most chunk_size - DeploymentLogEvent, each stored line at most once. Discover pod names with + inclusive), yielded lazily oldest first as chunks of DeploymentLogEvent, + each stored line at most once. Discover pod names with get_deployment_pods(). + chunk_size is the number of lines requested from the server per round + trip (1 to MAX_LOG_PAGE_LINES), and each server page becomes one yielded + chunk, so a bulk read of history wants a large chunk_size — the log read + path is rate-limited upstream, and a small chunk_size over a large window + multiplies requests. A chunk usually holds up to chunk_size lines but can + be smaller (lines below start_time or already delivered are filtered out + of the page) or larger (the server never splits one millisecond across + pages, so a millisecond holding more than chunk_size lines arrives + whole). + start_time defaults to the current time, resolved once when fetch_logs is called (not at the first next()), so lines logged while the generator sits unstarted are not skipped; pass an earlier start_time to read history. - With end_time set the iterator terminates once the window is delivered: - every chunk except possibly the last holds exactly chunk_size lines. - Without end_time it never terminates — once caught up it flushes any - partial chunk, then yields an empty chunk each time nothing new is stored - yet, and the caller decides when to sleep or break: + With end_time set the iterator terminates once the window is delivered. + Without end_time it never terminates — once caught up it yields an empty + chunk each time nothing new is stored yet, and the caller decides when to + sleep or break: for chunk in cclient.fetch_logs(dep, rev, pod): if not chunk: @@ -400,8 +409,12 @@ def fetch_logs( timestamp position, never duplicated; lines inside each chunk are always in ascending (timestamp, id) order. """ - if chunk_size < 1: - raise ValueError("chunk_size must be a positive number of lines") + if not 1 <= chunk_size <= MAX_LOG_PAGE_LINES: + raise ValueError( + f"chunk_size must be between 1 and {MAX_LOG_PAGE_LINES} lines " + "(chunk_size is also the per-request page size, and the server " + f"caps max_lines at {MAX_LOG_PAGE_LINES})" + ) if (start_time is not None and start_time < 0) or (end_time is not None and end_time < 0): raise ValueError("start_time and end_time are epoch milliseconds and must not be negative") if start_time is not None and end_time is not None and start_time > end_time: @@ -410,15 +423,13 @@ def fetch_logs( def chunks() -> Iterator[List[DeploymentLogEvent]]: held: list = [] - pending: List[DeploymentLogEvent] = [] # after is exclusive, so start_ms - 1 admits lines at start_ms itself. initial_boundary = max(start_ms - 1, 0) while True: anchor: Union[list, int] = _recent_anchor(held) if held else initial_boundary - page = self._fetch_log_page( - deployment_id, revision_number, pod, after=anchor, max_lines=MAX_LOG_PAGE_LINES - ) + page = self._fetch_log_page(deployment_id, revision_number, pod, after=anchor, max_lines=chunk_size) past_end = False + chunk: List[DeploymentLogEvent] = [] for raw in page: if held and raw.id <= held[-1].id: # Late arrival inside the look-behind span: keep the held window @@ -434,28 +445,23 @@ def chunks() -> Iterator[List[DeploymentLogEvent]]: past_end = True continue event = DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod) - # A late arrival re-delivered inside the look-behind span can sort - # below lines already pending; insort keeps every chunk ascending. - if pending and (event.timestamp, event.id) < (pending[-1].timestamp, pending[-1].id): - insort(pending, event, key=lambda pending_event: (pending_event.timestamp, pending_event.id)) + # The server orders a page by nanosecond timestamp only, never by + # the id's hash suffix, so lines sharing one nanosecond can arrive + # in either id order; insort keeps every chunk ascending. + if chunk and (event.timestamp, event.id) < (chunk[-1].timestamp, chunk[-1].id): + insort(chunk, event, key=lambda chunk_event: (chunk_event.timestamp, chunk_event.id)) else: - pending.append(event) + chunk.append(event) if held: held = _recent_anchor(held) - while len(pending) >= chunk_size: - yield pending[:chunk_size] - del pending[:chunk_size] + if chunk: + yield chunk if past_end or (not page and end_time is not None): break if not page: - # Caught up with no end bound: flush the partial chunk, then - # signal "nothing new yet" until new lines are stored. - if pending: - yield pending[:] - pending.clear() + # Caught up with no end bound: signal "nothing new yet" until + # new lines are stored. yield [] - if pending: - yield pending # The nested generator closes over the validated arguments, so the # ValueErrors above raise at the call rather than at the first next(). diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index dcfcae0..66f2571 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -24,13 +24,19 @@ def main(): # A window read: start_time/end_time are epoch ms, inclusive. With end_time # set the iterator terminates once the window is delivered. fetch_logs is - # lazy — chunks are yielded as they are fetched, with bounded memory - # however large the window. + # lazy — each server page is yielded as one chunk, with bounded memory + # however large the window. chunk_size is also the number of lines + # requested per round trip, so a bulk read wants a large value. now_ms = int(time.time() * 1000) print(f"Last {WINDOW_MINUTES} minutes of pod {pod}:\n") count = 0 for chunk in cclient.fetch_logs( - DEPLOYMENT_ID, REVISION_NUMBER, pod, start_time=now_ms - WINDOW_MINUTES * 60_000, end_time=now_ms + DEPLOYMENT_ID, + REVISION_NUMBER, + pod, + start_time=now_ms - WINDOW_MINUTES * 60_000, + end_time=now_ms, + chunk_size=1000, ): for event in chunk: print(format_event(event)) diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 54f23df..5ada44c 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -14,7 +14,13 @@ ) from centml.sdk import ApiException -from centml.sdk.api import LOG_DEDUP_RETENTION_MS, CentMLClient, DeploymentLogSession, get_centml_client +from centml.sdk.api import ( + LOG_DEDUP_RETENTION_MS, + MAX_LOG_PAGE_LINES, + CentMLClient, + DeploymentLogSession, + get_centml_client, +) from centml.sdk.config import settings @@ -695,33 +701,53 @@ def test_fetch_logs_yields_first_chunk_before_fetching_the_next_page(): assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 3 -def test_fetch_logs_chunk_size_shapes_the_yields(): +def test_fetch_logs_requests_the_callers_chunk_size_as_max_lines(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ - _log_page(*(_log_event(f"{1000 + i}-x", 1000 + i) for i in range(7))), + _log_page(_log_event("1-a", 1000)), _log_page(), ] client = CentMLClient(api) + list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=7)) + + # chunk_size is the server page size: every request carries it as max_lines. + calls = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list + assert [call.kwargs["max_lines"] for call in calls] == [7, 7] + + +def test_fetch_logs_millisecond_burst_larger_than_chunk_size_arrives_whole(): + # The server never splits one millisecond across pages, so a millisecond + # holding more than chunk_size lines comes back — and is yielded — whole. + burst = [_log_event(f"1000-{suffix}", 1000) for suffix in "abcdefg"] + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [_log_page(*burst), _log_page()] + client = CentMLClient(api) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=3)) - assert [len(chunk) for chunk in chunks] == [3, 3, 1] - assert [e.id for e in _flatten(chunks)] == [f"{1000 + i}-x" for i in range(7)] + assert [len(chunk) for chunk in chunks] == [7] + assert [e.id for e in chunks[0]] == [e.id for e in burst] -def test_fetch_logs_bounded_chunks_are_full_except_the_last(): - all_events = [_log_event(f"{1000 * i:05d}-x", 1000 * i) for i in range(1, 12)] +def test_fetch_logs_chunk_comes_back_short_when_the_page_is_filtered(): api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( - all_events, page_cap=4 - ) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + # The first page re-delivers the look-behind span below start_time; those + # lines are held for dedup but not emitted, so the chunk is short. + _log_page( + _log_event("04990-w", 4990), + _log_event("04995-x", 4995), + _log_event("05000-y", 5000), + _log_event("06000-z", 6000), + ), + _log_page(), + ] client = CentMLClient(api) - chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=20_000, chunk_size=3)) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=5000, end_time=10_000, chunk_size=4)) - assert [len(chunk) for chunk in chunks] == [3, 3, 3, 2] - for chunk in chunks: - assert [(e.timestamp, e.id) for e in chunk] == sorted((e.timestamp, e.id) for e in chunk) + assert [[e.id for e in chunk] for chunk in chunks] == [["05000-y", "06000-z"]] def test_fetch_logs_start_time_defaults_to_now_resolved_at_the_call(): @@ -774,7 +800,7 @@ def test_fetch_logs_open_ended_yields_empty_chunks_and_resumes_without_duplicate api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), - _log_page(), # caught up: flush the partial chunk, then "nothing new yet" + _log_page(), # caught up: "nothing new yet" _log_page(), # still nothing _log_page(_log_event("2-b", 2000), _log_event("3-c", 3000)), # look-behind re-delivers 2-b _log_page(), @@ -873,16 +899,32 @@ def test_fetch_logs_late_arrival_lands_in_a_later_chunk_still_ascending(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ _log_page(_log_event("01000-a", 1000), _log_event("02000-b", 2000), _log_event("03000-c", 3000)), - # A late arrival re-delivered inside the look-behind span sorts below the - # pending line 03000-c; every chunk must still be internally ascending. + # A late arrival re-delivered inside the look-behind span lands in the + # chunk of the page that carried it, below that page's fresh lines. _log_page(_log_event("02500-l", 2500), _log_event("04000-d", 4000)), _log_page(), ] client = CentMLClient(api) - chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=2)) + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=3)) + + assert [[e.id for e in chunk] for chunk in chunks] == [["01000-a", "02000-b", "03000-c"], ["02500-l", "04000-d"]] + + +def test_fetch_logs_chunk_stays_ascending_when_the_server_ties_on_timestamp(): + # The server sorts a page by nanosecond timestamp only, so two lines sharing + # one nanosecond can arrive in either id order; the chunk must still come out + # ascending in (timestamp, id). + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1000-b", 1000), _log_event("1000-a", 1000), _log_event("2000-c", 2000)), + _log_page(), + ] + client = CentMLClient(api) + + chunks = list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=5)) - assert [[e.id for e in chunk] for chunk in chunks] == [["01000-a", "02000-b"], ["02500-l", "03000-c"], ["04000-d"]] + assert [[e.id for e in chunk] for chunk in chunks] == [["1000-a", "1000-b", "2000-c"]] def test_fetch_logs_validates_eagerly_at_the_call_not_the_first_next(): @@ -891,7 +933,15 @@ def test_fetch_logs_validates_eagerly_at_the_call_not_the_first_next(): # Each ValueError is raised by the call itself — never deferred to next() — # so a stored or passed-around iterator cannot surface it far from the bad call. - for kwargs in ({"start_time": 2000, "end_time": 1000}, {"start_time": -1}, {"end_time": -1}, {"chunk_size": 0}): + for kwargs in ( + {"start_time": 2000, "end_time": 1000}, + {"start_time": -1}, + {"end_time": -1}, + {"chunk_size": 0}, + # chunk_size is the on-the-wire page size, so it inherits the server's + # ceiling — rejected here, not by a generated-model pydantic error. + {"chunk_size": MAX_LOG_PAGE_LINES + 1}, + ): with pytest.raises(ValueError): client.fetch_logs(123, 2, pod="pod-a", **kwargs) From 0ae1fa3b2b2b6f8b81c2e963860c04c206078e8a Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 14:06:06 -0400 Subject: [PATCH 14/22] Document resuming fetch_logs after a failed page A page request that fails takes the generator with it, but every chunk already yielded is complete and the next one has not been started. Say so, and give the resume recipe: start_time is inclusive, so re-anchoring on the last delivered event's timestamp re-delivers only that millisecond. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index b529650..1c197b6 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -408,6 +408,13 @@ def fetch_logs( A line the log store received late lands in a later chunk than its timestamp position, never duplicated; lines inside each chunk are always in ascending (timestamp, id) order. + + If a page request fails the iterator raises and, like any generator, + cannot be resumed — but every chunk already yielded is complete and none + is left half-built. Resume with a new fetch_logs whose start_time is the + last delivered event's timestamp: bounds are inclusive, so the only lines + delivered again are the ones sharing that millisecond, which the caller + already holds. """ if not 1 <= chunk_size <= MAX_LOG_PAGE_LINES: raise ValueError( From 523a7c1d9750264a150251c348d91cfc24be0a74 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 14:34:49 -0400 Subject: [PATCH 15/22] Correct the fetch_logs contract and restore the example guard State three things the docs got wrong: a bounded read also ends when the store runs out of lines, so a future end_time does not keep it polling; the dedup window is LOG_DEDUP_RETENTION_MS, not the server's span; and a line landing further behind the boundary than that span is never returned at all, because this reader only pages forward. Hold ids and timestamps in the anchor instead of whole events, so a long tail stops retaining message text it has already handed out. Break out of the page once one line passes end_time, and skip the retention trim on the empty pages of an idle tail. Restore the example's empty-pod-list guard, dropped in the rewrite: a fresh deployment has no pods and the example raised IndexError. Revert the DeploymentLogEvent docstring and the get_deployment_logs page-ceiling paragraph to main; neither method changed behaviour here. Drop the draft narration from the livelock test comment and name the span the way the SDK does everywhere else. Cover the failed-page contract, start_time=0 clamping, and both ends of the chunk_size range. Signed-off-by: Honglin Cao --- README.md | 8 ++-- centml/sdk/api.py | 45 ++++++++++++++------- examples/sdk/get_deployment_logs.py | 13 ++++-- tests/test_sdk_api.py | 62 +++++++++++++++++++++++++---- 4 files changed, 99 insertions(+), 29 deletions(-) diff --git a/README.md b/README.md index bbc99fd..8918fe9 100644 --- a/README.md +++ b/README.md @@ -58,14 +58,16 @@ delete the deployment automatically. `fetch_logs()` is the one way to read deployment logs: it fetches one pod's stored log lines within a time window (`start_time`/`end_time`, epoch ms, inclusive) and yields them lazily, oldest first, as chunks of `DeploymentLogEvent` — each line at -most once, with bounded memory however long the stream. `chunk_size` (1 to 5000) +most once, holding only a short dedup window in memory however long the stream. +`chunk_size` (1 to 5000) is the number of lines requested from the server per round trip and each server page becomes one chunk, so a bulk read of history wants a large `chunk_size` — the log read path is rate-limited upstream, and a small `chunk_size` over a large window multiplies requests. Discover pod names with `get_deployment_pods()` (terminated pods still within log retention are included). `start_time` defaults to the moment of the call; with `end_time` set the iterator terminates once the -window is delivered: +window is delivered or the store has no more lines to give, whichever comes +first: ```python for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod, start_time=t1_ms, end_time=t2_ms): @@ -90,7 +92,7 @@ for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod): `python examples/sdk/get_deployment_logs.py` runs both. `get_deployment_logs()`, `get_deployment_logs_range()` and `deployment_log_session()` still work but are -deprecated in favor of `fetch_logs()` and raise a `DeprecationWarning` on use. +deprecated in favor of `fetch_logs()` and emit a `DeprecationWarning` on use. ### Un-installation diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 1c197b6..0188e18 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -45,10 +45,20 @@ def _recent_anchor(events: list) -> list: return events[first_recent:] +@dataclass(frozen=True) +class _LogAnchor: + """All an after anchor takes from an event: the dedup id and the timestamp the + boundary and the retention trim read. Holding these instead of whole events keeps + a long-running fetch_logs off the message text it has already handed out.""" + + id: str + timestamp: int + + @dataclass(frozen=True) class DeploymentLogEvent: """One log line with its pod attached — logs_v4 events carry no pod name, so - the SDK attributes each line to the pod it was fetched from.""" + merged multi-pod views need the SDK to attribute each line itself.""" id: str timestamp: int @@ -261,10 +271,7 @@ def get_deployment_logs( boundary itself — after=0 scans from the head of the log window; an int after anchor holds no event ids, so the re-delivered span at the boundary comes through undeduplicated. An empty anchor list raises ValueError. Pages never - split a millisecond, so a delivered boundary millisecond is complete unless it - holds more than the log store's 5000-line per-query ceiling — past that the page - carries the 5000 nearest its direction (the newest when paging older, the oldest - when paging newer), independently of max_lines. + split a millisecond, so a delivered boundary millisecond is always complete. """ return self._fetch_log_page( deployment_id, revision_number, pod, before=before, after=after, max_lines=max_lines @@ -391,7 +398,9 @@ def fetch_logs( called (not at the first next()), so lines logged while the generator sits unstarted are not skipped; pass an earlier start_time to read history. - With end_time set the iterator terminates once the window is delivered. + With end_time set the iterator terminates once the window is delivered or + the store has no more lines to give, whichever comes first — an end_time + in the future does not keep it polling until then. Without end_time it never terminates — once caught up it yields an empty chunk each time nothing new is stored yet, and the caller decides when to sleep or break: @@ -402,11 +411,18 @@ def fetch_logs( continue ... - Nothing is fetched before the first next(), and memory stays bounded - however long the stream: the dedup anchor is trimmed to the server's ~15s - re-delivery span, so no line is delivered twice — across empty chunks too. + Nothing is fetched before the first next(), and memory is bounded by the + dedup window rather than by the length of the stream: the anchor holds + only the ids and timestamps of the last LOG_DEDUP_RETENTION_MS, a + generous margin over the server's re-delivery span, so no line is + delivered twice — across empty chunks too. + A line the log store received late lands in a later chunk than its - timestamp position, never duplicated; lines inside each chunk are always + timestamp position, never duplicated, as long as it lands inside that + re-delivery span (~15s). This reader only ever pages forward, and the + server re-delivers the span behind the boundary only; a line whose + timestamp falls further than the span behind the newest line already + delivered is never returned at all. Lines inside each chunk are always in ascending (timestamp, id) order. If a page request fails the iterator raises and, like any generator, @@ -438,19 +454,20 @@ def chunks() -> Iterator[List[DeploymentLogEvent]]: past_end = False chunk: List[DeploymentLogEvent] = [] for raw in page: + anchor_event = _LogAnchor(id=raw.id, timestamp=raw.timestamp) if held and raw.id <= held[-1].id: # Late arrival inside the look-behind span: keep the held window # id-ordered (id order == time order) so trimming stays correct. - insort(held, raw, key=lambda held_event: held_event.id) + insort(held, anchor_event, key=lambda held_event: held_event.id) else: - held.append(raw) + held.append(anchor_event) # Anchoring at start_ms - 1 re-delivers the look-behind span below # start_ms; those ids must be held for dedup but never emitted. if raw.timestamp < start_ms: continue if end_time is not None and raw.timestamp > end_time: past_end = True - continue + break event = DeploymentLogEvent(id=raw.id, timestamp=raw.timestamp, message=raw.message, pod=pod) # The server orders a page by nanosecond timestamp only, never by # the id's hash suffix, so lines sharing one nanosecond can arrive @@ -459,7 +476,7 @@ def chunks() -> Iterator[List[DeploymentLogEvent]]: insort(chunk, event, key=lambda chunk_event: (chunk_event.timestamp, chunk_event.id)) else: chunk.append(event) - if held: + if page: held = _recent_anchor(held) if chunk: yield chunk diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index 66f2571..442bb7c 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -20,13 +20,18 @@ def main(): with get_centml_client() as cclient: # Discover pod names; terminated pods still within log retention are included. pods = cclient.get_deployment_pods(DEPLOYMENT_ID, REVISION_NUMBER) + if not pods: + print("No pods have logged for this revision yet.") + return + pod = pods[0] # A window read: start_time/end_time are epoch ms, inclusive. With end_time - # set the iterator terminates once the window is delivered. fetch_logs is - # lazy — each server page is yielded as one chunk, with bounded memory - # however large the window. chunk_size is also the number of lines - # requested per round trip, so a bulk read wants a large value. + # set the iterator terminates once the window is delivered or the store has + # no more lines to give. fetch_logs is lazy — each server page is yielded as + # one chunk, and only a short dedup window is held however large the read. + # chunk_size is also the number of lines requested per round trip, so a bulk + # read wants a large value. now_ms = int(time.time() * 1000) print(f"Last {WINDOW_MINUTES} minutes of pod {pod}:\n") count = 0 diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 5ada44c..ca882d9 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -672,8 +672,8 @@ def respond(**kwargs): limit = min(kwargs["max_lines"], page_cap or kwargs["max_lines"]) boundary = kwargs["timestamp"] newer = [e for e in all_events if e.timestamp > boundary][:limit] - gray = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] - return _log_page(*sorted(gray + newer, key=lambda e: e.id)) + look_behind = [e for e in all_events if boundary - look_behind_ms < e.timestamp <= boundary] + return _log_page(*sorted(look_behind + newer, key=lambda e: e.id)) return respond @@ -820,11 +820,10 @@ def test_fetch_logs_open_ended_yields_empty_chunks_and_resumes_without_duplicate assert next(stream) == [] -def test_fetch_logs_does_not_livelock_on_gray_span_redelivery(): - # Regression: with a bare int boundary the re-delivered look-behind span keeps - # every page non-empty forever (measured against dev: 9 iterations of the same - # 7 gray lines before the naive port was declared wedged). The held anchor - # dedupes the gray span away, so the bounded read terminates. +def test_fetch_logs_does_not_livelock_on_look_behind_redelivery(): + # A bare int boundary alone would never terminate: the re-delivered look-behind + # span keeps every page non-empty and the boundary never advances past it. The + # held anchor dedupes the span away, so the bounded read terminates. all_events = [_log_event(f"{1000 + i:05d}-x", 1000 + i) for i in range(30)] api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = _replaying_log_server( @@ -839,7 +838,7 @@ def test_fetch_logs_does_not_livelock_on_gray_span_redelivery(): assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 4 -def test_fetch_logs_start_time_holds_gray_lines_below_the_window(): +def test_fetch_logs_start_time_holds_look_behind_lines_below_the_window(): all_events = [ _log_event("04990-w", 4990), _log_event("04995-x", 4995), @@ -948,6 +947,53 @@ def test_fetch_logs_validates_eagerly_at_the_call_not_the_first_next(): api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_not_called() +def test_fetch_logs_accepts_both_ends_of_the_chunk_size_range(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() + client = CentMLClient(api) + + for chunk_size in (1, MAX_LOG_PAGE_LINES): + list(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=chunk_size)) + + sent = [ + call.kwargs["max_lines"] + for call in api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list + ] + assert sent == [1, MAX_LOG_PAGE_LINES] + + +def test_fetch_logs_start_time_zero_clamps_the_boundary(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page() + client = CentMLClient(api) + + list(client.fetch_logs(123, 2, pod="pod-a", start_time=0, end_time=10_000)) + + # after is exclusive, but the server rejects a negative boundary, so start_time 0 + # clamps to 0 — which already admits every stored line. + first_call = api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_args_list[0] + assert first_call.kwargs["timestamp"] == 0 + + +def test_fetch_logs_failed_page_leaves_delivered_chunks_whole(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), + ApiException(status=503), + ] + client = CentMLClient(api) + + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=2) + + assert [e.id for e in next(stream)] == ["1-a", "2-b"] + with pytest.raises(ApiException): + next(stream) + # The failure ends the iterator, as it would any generator; the caller resumes + # with a new fetch_logs anchored on the last event it holds. + with pytest.raises(StopIteration): + next(stream) + + def test_fetch_logs_is_lazy_until_the_first_next(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page(_log_event("1-a", 1000)) From 30f4fabcf4ad3732d243c4a87ff3826ab0f58d99 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 14:42:50 -0400 Subject: [PATCH 16/22] Say what a fully filtered log page yields A page whose lines are all below start_time or all already delivered produces no chunk at all, not the empty chunk that means the stream is caught up. The docstring and README claimed every page becomes a chunk; say what actually happens and pin it with a test. Signed-off-by: Honglin Cao --- README.md | 10 +++++----- centml/sdk/api.py | 24 +++++++++++++----------- tests/test_sdk_api.py | 16 ++++++++++++++++ 3 files changed, 34 insertions(+), 16 deletions(-) diff --git a/README.md b/README.md index 8918fe9..fccd905 100644 --- a/README.md +++ b/README.md @@ -59,11 +59,11 @@ delete the deployment automatically. log lines within a time window (`start_time`/`end_time`, epoch ms, inclusive) and yields them lazily, oldest first, as chunks of `DeploymentLogEvent` — each line at most once, holding only a short dedup window in memory however long the stream. -`chunk_size` (1 to 5000) -is the number of lines requested from the server per round trip and each server -page becomes one chunk, so a bulk read of history wants a large `chunk_size` — -the log read path is rate-limited upstream, and a small `chunk_size` over a large -window multiplies requests. Discover pod names with `get_deployment_pods()` +`chunk_size` (1 to 5000) is the number of lines requested from the server per +round trip and each server page that carries window lines becomes one chunk, so +a bulk read of history wants a large `chunk_size` — the log read path is +rate-limited upstream, and a small `chunk_size` over a large window multiplies +requests. Discover pod names with `get_deployment_pods()` (terminated pods still within log retention are included). `start_time` defaults to the moment of the call; with `end_time` set the iterator terminates once the window is delivered or the store has no more lines to give, whichever comes diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 0188e18..84c92d5 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -47,9 +47,9 @@ def _recent_anchor(events: list) -> list: @dataclass(frozen=True) class _LogAnchor: - """All an after anchor takes from an event: the dedup id and the timestamp the - boundary and the retention trim read. Holding these instead of whole events keeps - a long-running fetch_logs off the message text it has already handed out.""" + """The two fields an after anchor uses: the id it dedupes by and the timestamp it + takes its boundary and its retention cutoff from. Holding these instead of whole + events keeps a long tail off the message text it has already handed out.""" id: str timestamp: int @@ -385,14 +385,16 @@ def fetch_logs( get_deployment_pods(). chunk_size is the number of lines requested from the server per round - trip (1 to MAX_LOG_PAGE_LINES), and each server page becomes one yielded - chunk, so a bulk read of history wants a large chunk_size — the log read - path is rate-limited upstream, and a small chunk_size over a large window - multiplies requests. A chunk usually holds up to chunk_size lines but can - be smaller (lines below start_time or already delivered are filtered out - of the page) or larger (the server never splits one millisecond across - pages, so a millisecond holding more than chunk_size lines arrives - whole). + trip (1 to MAX_LOG_PAGE_LINES), and each server page that carries window + lines becomes one yielded chunk, so a bulk read of history wants a large + chunk_size — the log read path is rate-limited upstream, and a small + chunk_size over a large window multiplies requests. A chunk usually holds + up to chunk_size lines but can be smaller (lines below start_time or + already delivered are filtered out of the page) or larger (the server + never splits one millisecond across pages, so a millisecond holding more + than chunk_size lines arrives whole). A page filtered away entirely + yields nothing at all rather than an empty chunk, which means only that + the stream is caught up. start_time defaults to the current time, resolved once when fetch_logs is called (not at the first next()), so lines logged while the generator sits diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index ca882d9..2a15067 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -857,6 +857,22 @@ def test_fetch_logs_start_time_holds_look_behind_lines_below_the_window(): assert first_call.kwargs["timestamp"] == 4999 # after is exclusive: admits start_time itself +def test_fetch_logs_page_filtered_away_entirely_yields_nothing_not_an_empty_chunk(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("04990-w", 4990), _log_event("04995-x", 4995)), + _log_page(_log_event("06000-z", 6000)), + ] + client = CentMLClient(api) + + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=5000) + + # An empty chunk means "caught up", so a page holding only look-behind lines + # below start_time must fetch again rather than claim the stream is idle. + assert [e.id for e in next(stream)] == ["06000-z"] + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == 2 + + def test_fetch_logs_held_state_stays_within_the_dedup_window(): step_ms = 10_000 pages = [ From f6cbc3df75f57ca0bdb980498ff89570c963a2c3 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 14:58:40 -0400 Subject: [PATCH 17/22] Stop suppressing warnings around the session constructor warnings.catch_warnings swaps the module-global filter list, not a thread-local one, so the window silently dropped every other thread's DeprecationWarning for the duration of the construction. Keeping it cost more than the duplicate warning it hid, and the two warnings are not redundant: one names the factory the caller used, the other the class it keeps using afterwards. Without it the method body is main's again, and warnings is no longer imported. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 7 +------ tests/test_sdk_api.py | 9 ++++++--- 2 files changed, 7 insertions(+), 9 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 84c92d5..c11d877 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -1,5 +1,4 @@ import time -import warnings from bisect import insort from contextlib import contextmanager from dataclasses import dataclass @@ -502,11 +501,7 @@ def deployment_log_session( Stateful reader for one pod's logs that tracks fetched pages and anchors every request itself — see DeploymentLogSession. Seed events with logs a previous session (or get_deployment_logs) returned for the same pod.""" - with warnings.catch_warnings(): - # This call already warned via its own decorator; constructing the - # (also-deprecated) session class must not warn a second time. - warnings.simplefilter("ignore", DeprecationWarning) - return DeploymentLogSession(self, deployment_id, revision_number, pod, events) + return DeploymentLogSession(self, deployment_id, revision_number, pod, events) @deprecated("DeploymentLogSession is deprecated; use CentMLClient.fetch_logs() instead") diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 2a15067..3593da3 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -1051,9 +1051,12 @@ def test_deprecated_log_readers_warn_and_name_the_replacement(): client.get_deployment_logs_range(123, 2) with pytest.warns(DeprecationWarning, match="fetch_logs") as caught: session = client.deployment_log_session(123, 2, "pod-a") - # Exactly one warning: the method's own, not a second from constructing the - # (also-deprecated) session class inside it. - assert len(caught) == 1 + # Two warnings, one per deprecated surface the call crosses: the factory the + # caller named, and the session class it hands back for the caller to keep using. + assert [str(warning.message) for warning in caught] == [ + "deployment_log_session() is deprecated; use fetch_logs() instead", + "DeploymentLogSession is deprecated; use CentMLClient.fetch_logs() instead", + ] with pytest.warns(DeprecationWarning, match="fetch_logs"): DeploymentLogSession(client, 123, 2, "pod-a") From 0fc124dcedc2de08ebf9a5ecf7ff21a4e9818efd Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 15:21:49 -0400 Subject: [PATCH 18/22] Retry fetch_logs pages the store answers as busy The read path is rate limited upstream on a bucket shared by every caller, and fetch_logs is the reader that reaches it: chunk_size is the request size, so the default walks a large window in thousands of round trips. A 503 used to take the generator with it, losing the anchor and the position that make the caller's bookkeeping unnecessary in the first place. There is no server-issued cursor, so a page request is a pure function of its anchor and re-issuing it can neither duplicate nor skip lines. Retry inside the loop, where the anchor is still in scope, with exponential backoff and jitter against the shared bucket, honouring Retry-After when the server sends one. Only 503 retries: a rejected request does not get better by repetition. Only fetch_logs. The single-page readers lose nothing when a page fails and their callers can decide for themselves whether to wait. Signed-off-by: Honglin Cao --- centml/sdk/api.py | 48 +++++++++++++++++++++++++++++++--- tests/test_sdk_api.py | 61 ++++++++++++++++++++++++++++++++++++++++++- 2 files changed, 104 insertions(+), 5 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index c11d877..872aef7 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -1,3 +1,4 @@ +import random import time from bisect import insort from contextlib import contextmanager @@ -31,6 +32,35 @@ # The server re-delivers a ~15s look-behind window on fetch-newer requests; only the # caller's events within this generous margin of the boundary can be re-delivered. LOG_DEDUP_RETENTION_MS = 300_000 +# The log read path is rate limited upstream on a bucket shared by every caller, and the +# API reports a saturated bucket the same way it reports a sick store: HTTP 503. The +# budget spans a few seconds, long enough to outlast a bucket refill without looking hung. +LOG_BUSY_STATUS = 503 +LOG_RETRY_ATTEMPTS = 5 +LOG_RETRY_BASE_SECONDS = 0.5 +LOG_RETRY_MAX_SECONDS = 8.0 + + +def _with_busy_retry(fetch_page): + """Call fetch_page, retrying while the store reports itself busy. There is no + server-issued cursor, so a page request is a pure function of its anchor and + re-issuing it can neither duplicate nor skip lines.""" + for attempt in range(LOG_RETRY_ATTEMPTS - 1): + try: + return fetch_page() + except ApiException as exc: + if exc.status != LOG_BUSY_STATUS: + raise + retry_after = exc.headers.get("Retry-After") if exc.headers else None + if retry_after is not None and retry_after.isdigit(): + delay = min(float(retry_after), LOG_RETRY_MAX_SECONDS) + else: + # jitter: the bucket is shared, so unjittered clients re-collide on it + backoff = min(LOG_RETRY_BASE_SECONDS * 2**attempt, LOG_RETRY_MAX_SECONDS) + delay = backoff * (0.75 + random.random() * 0.5) + time.sleep(delay) + # the last attempt propagates whatever it raises + return fetch_page() def _recent_anchor(events: list) -> list: @@ -426,9 +456,15 @@ def fetch_logs( delivered is never returned at all. Lines inside each chunk are always in ascending (timestamp, id) order. - If a page request fails the iterator raises and, like any generator, - cannot be resumed — but every chunk already yielded is complete and none - is left half-built. Resume with a new fetch_logs whose start_time is the + A page request the store answers as busy (HTTP 503) is retried with + exponential backoff and jitter, honouring Retry-After when the server + sends one; the anchor survives the retry, so an upstream rate limit costs + a pause rather than the stream. + + If a page request fails for any other reason, or the retries run out, the + iterator raises and, like any generator, cannot be resumed — but every + chunk already yielded is complete and none is left half-built. Resume + with a new fetch_logs whose start_time is the last delivered event's timestamp: bounds are inclusive, so the only lines delivered again are the ones sharing that millisecond, which the caller already holds. @@ -451,7 +487,11 @@ def chunks() -> Iterator[List[DeploymentLogEvent]]: initial_boundary = max(start_ms - 1, 0) while True: anchor: Union[list, int] = _recent_anchor(held) if held else initial_boundary - page = self._fetch_log_page(deployment_id, revision_number, pod, after=anchor, max_lines=chunk_size) + page = _with_busy_retry( + lambda anchor=anchor: self._fetch_log_page( + deployment_id, revision_number, pod, after=anchor, max_lines=chunk_size + ) + ) past_end = False chunk: List[DeploymentLogEvent] = [] for raw in page: diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 3593da3..2ccf7de 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -16,6 +16,7 @@ from centml.sdk import ApiException from centml.sdk.api import ( LOG_DEDUP_RETENTION_MS, + LOG_RETRY_ATTEMPTS, MAX_LOG_PAGE_LINES, CentMLClient, DeploymentLogSession, @@ -995,7 +996,7 @@ def test_fetch_logs_failed_page_leaves_delivered_chunks_whole(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), - ApiException(status=503), + ApiException(status=400), ] client = CentMLClient(api) @@ -1010,6 +1011,64 @@ def test_fetch_logs_failed_page_leaves_delivered_chunks_whole(): next(stream) +def test_fetch_logs_survives_a_busy_store_without_losing_its_anchor(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000)), + ApiException(status=503), + _log_page(_log_event("1-a", 1000), _log_event("2-b", 2000)), + _log_page(), + ] + client = CentMLClient(api) + + with patch("centml.sdk.api.time.sleep"): + events = _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) + + # The retry re-issues the same anchored request, so the line it re-delivers is + # deduped rather than emitted twice, and the stream survives the rate limit. + assert [e.id for e in events] == ["1-a", "2-b"] + + +def test_fetch_logs_gives_up_on_a_busy_store_after_the_retry_budget(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=503) + client = CentMLClient(api) + + with patch("centml.sdk.api.time.sleep") as sleep: + with pytest.raises(ApiException): + next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) + + assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == LOG_RETRY_ATTEMPTS + assert sleep.call_count == LOG_RETRY_ATTEMPTS - 1 + + +def test_fetch_logs_does_not_retry_a_request_the_store_rejects(): + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=404) + client = CentMLClient(api) + + with patch("centml.sdk.api.time.sleep") as sleep: + with pytest.raises(ApiException): + next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) + + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once() + sleep.assert_not_called() + + +def test_fetch_logs_waits_the_retry_after_the_store_asks_for(): + busy = ApiException(status=503) + busy.headers = {"Retry-After": "2"} + api = MagicMock() + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [busy, _log_page()] + client = CentMLClient(api) + + with patch("centml.sdk.api.time.sleep") as sleep: + assert _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) == [] + + # Honoured verbatim, not jittered: the server named the delay. + sleep.assert_called_once_with(2.0) + + def test_fetch_logs_is_lazy_until_the_first_next(): api = MagicMock() api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.return_value = _log_page(_log_event("1-a", 1000)) From d4bd070ec9ee945ef1c8ed4ad95015412db08b46 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 15:31:10 -0400 Subject: [PATCH 19/22] Drop the unreachable arms of the busy-page backoff MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- centml/sdk/api.py | 40 ++++++++++++++++++---------------------- tests/test_sdk_api.py | 42 ++++++++++++++++++++++++++---------------- 2 files changed, 44 insertions(+), 38 deletions(-) diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 872aef7..662bc7a 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -33,12 +33,15 @@ # caller's events within this generous margin of the boundary can be re-delivered. LOG_DEDUP_RETENTION_MS = 300_000 # The log read path is rate limited upstream on a bucket shared by every caller, and the -# API reports a saturated bucket the same way it reports a sick store: HTTP 503. The -# budget spans a few seconds, long enough to outlast a bucket refill without looking hung. +# API reports a saturated bucket the same way it reports a sick store: HTTP 503. Doubling +# from half a second spends about seven seconds over the budget below — long enough to +# outlast a bucket refill without looking hung. LOG_BUSY_STATUS = 503 LOG_RETRY_ATTEMPTS = 5 LOG_RETRY_BASE_SECONDS = 0.5 -LOG_RETRY_MAX_SECONDS = 8.0 +# Fraction of each backoff to vary it by: the bucket is shared, so clients backing off in +# lockstep would re-collide on it every round. +LOG_RETRY_JITTER = 0.25 def _with_busy_retry(fetch_page): @@ -51,14 +54,8 @@ def _with_busy_retry(fetch_page): except ApiException as exc: if exc.status != LOG_BUSY_STATUS: raise - retry_after = exc.headers.get("Retry-After") if exc.headers else None - if retry_after is not None and retry_after.isdigit(): - delay = min(float(retry_after), LOG_RETRY_MAX_SECONDS) - else: - # jitter: the bucket is shared, so unjittered clients re-collide on it - backoff = min(LOG_RETRY_BASE_SECONDS * 2**attempt, LOG_RETRY_MAX_SECONDS) - delay = backoff * (0.75 + random.random() * 0.5) - time.sleep(delay) + backoff = LOG_RETRY_BASE_SECONDS * 2**attempt + time.sleep(backoff * (1 + random.uniform(-LOG_RETRY_JITTER, LOG_RETRY_JITTER))) # the last attempt propagates whatever it raises return fetch_page() @@ -457,17 +454,16 @@ def fetch_logs( in ascending (timestamp, id) order. A page request the store answers as busy (HTTP 503) is retried with - exponential backoff and jitter, honouring Retry-After when the server - sends one; the anchor survives the retry, so an upstream rate limit costs - a pause rather than the stream. - - If a page request fails for any other reason, or the retries run out, the - iterator raises and, like any generator, cannot be resumed — but every - chunk already yielded is complete and none is left half-built. Resume - with a new fetch_logs whose start_time is the - last delivered event's timestamp: bounds are inclusive, so the only lines - delivered again are the ones sharing that millisecond, which the caller - already holds. + exponential backoff and jitter; the anchor survives the retry, so an + upstream rate limit costs a pause rather than the stream. + + If a page request fails for any other reason, or the retries run out, + the iterator raises and, like any generator, cannot be resumed — but + every chunk already yielded is complete and none is left half-built. + Resume with a new fetch_logs whose start_time is the last delivered + event's timestamp: bounds are inclusive, so the only lines delivered + again are the ones sharing that millisecond, which the caller already + holds. """ if not 1 <= chunk_size <= MAX_LOG_PAGE_LINES: raise ValueError( diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index 2ccf7de..fc8174a 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -17,6 +17,8 @@ from centml.sdk.api import ( LOG_DEDUP_RETENTION_MS, LOG_RETRY_ATTEMPTS, + LOG_RETRY_BASE_SECONDS, + LOG_RETRY_JITTER, MAX_LOG_PAGE_LINES, CentMLClient, DeploymentLogSession, @@ -1031,42 +1033,50 @@ def test_fetch_logs_survives_a_busy_store_without_losing_its_anchor(): def test_fetch_logs_gives_up_on_a_busy_store_after_the_retry_budget(): api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=503) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ + _log_page(_log_event("1-a", 1000)) + ] + [ApiException(status=503)] * LOG_RETRY_ATTEMPTS client = CentMLClient(api) + stream = client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000, chunk_size=1) + assert [e.id for e in next(stream)] == ["1-a"] + with patch("centml.sdk.api.time.sleep") as sleep: with pytest.raises(ApiException): - next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) + next(stream) - assert api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.call_count == LOG_RETRY_ATTEMPTS + # The whole budget goes on the one page, and the chunk already delivered stands. assert sleep.call_count == LOG_RETRY_ATTEMPTS - 1 -def test_fetch_logs_does_not_retry_a_request_the_store_rejects(): +def test_fetch_logs_backs_off_further_on_each_busy_answer(): api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=404) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [ApiException(status=503)] * ( + LOG_RETRY_ATTEMPTS - 1 + ) + [_log_page()] client = CentMLClient(api) with patch("centml.sdk.api.time.sleep") as sleep: - with pytest.raises(ApiException): - next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) + assert _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) == [] - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once() - sleep.assert_not_called() + waited = [call.args[0] for call in sleep.call_args_list] + assert len(waited) == LOG_RETRY_ATTEMPTS - 1 + for attempt, seconds in enumerate(waited): + nominal = LOG_RETRY_BASE_SECONDS * 2**attempt + assert nominal * (1 - LOG_RETRY_JITTER) <= seconds <= nominal * (1 + LOG_RETRY_JITTER) -def test_fetch_logs_waits_the_retry_after_the_store_asks_for(): - busy = ApiException(status=503) - busy.headers = {"Retry-After": "2"} +def test_fetch_logs_does_not_retry_a_request_the_store_rejects(): api = MagicMock() - api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = [busy, _log_page()] + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.side_effect = ApiException(status=404) client = CentMLClient(api) with patch("centml.sdk.api.time.sleep") as sleep: - assert _flatten(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) == [] + with pytest.raises(ApiException): + next(client.fetch_logs(123, 2, pod="pod-a", start_time=1, end_time=10_000)) - # Honoured verbatim, not jittered: the server named the delay. - sleep.assert_called_once_with(2.0) + api.get_deployment_logs_v4_logs_deployment_id_revision_number_get.assert_called_once() + sleep.assert_not_called() def test_fetch_logs_is_lazy_until_the_first_next(): From 5befb250b17cfa6d161d0af7b5dece893a56920f Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 16:09:28 -0400 Subject: [PATCH 20/22] Re-derive the chunk_size default and clear the merge-era leftovers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The default was 10 back when a buffer sat between the wire page and the chunk, and nothing re-derived it once chunk_size became the page size itself. The value still suits the common call — a tail, where the store has a handful of new lines to give whatever the page size — so keep it, but name it and say why it sits below the server's own page default. Attributing each line to its pod only made sense while one call could merge several pods. It cannot any more: pod is required and the example already names it in the header. The example's formatter is main's again. Carry the fully-filtered-page correction into the example comment, the third copy of a sentence the last commit fixed in two. Bind the page call with partial rather than a lambda default argument: same protection against the loop variable, and the callable types cleanly. Assert that each backoff outgrows the last instead of restating the expression that produces it. Signed-off-by: Honglin Cao --- README.md | 4 ++-- centml/sdk/api.py | 23 ++++++++++++++--------- examples/sdk/get_deployment_logs.py | 10 +++++----- tests/test_sdk_api.py | 8 +++----- 4 files changed, 24 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index fccd905..ffb3b09 100644 --- a/README.md +++ b/README.md @@ -72,7 +72,7 @@ first: ```python for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod, start_time=t1_ms, end_time=t2_ms): for event in chunk: - print(event.pod, event.message) + print(event.message) ``` Without `end_time` the same generator tails: it never terminates, and once caught @@ -87,7 +87,7 @@ for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION, pod): time.sleep(2) continue for event in chunk: - print(event.pod, event.message) + print(event.message) ``` `python examples/sdk/get_deployment_logs.py` runs both. `get_deployment_logs()`, diff --git a/centml/sdk/api.py b/centml/sdk/api.py index 662bc7a..3419652 100644 --- a/centml/sdk/api.py +++ b/centml/sdk/api.py @@ -3,7 +3,8 @@ from bisect import insort from contextlib import contextmanager from dataclasses import dataclass -from typing import Iterator, List, Optional, Union +from functools import partial +from typing import Callable, Iterator, List, Optional, Union import platform_api_python_client from platform_api_python_client import ( @@ -29,14 +30,18 @@ DEFAULT_LOG_PAGE_LINES = 100 # server-side default for max_lines MAX_LOG_PAGE_LINES = 5000 # server-side ceiling for max_lines +# fetch_logs asks for less than the server's own default because the common call tails a +# running deployment, where the store has only a handful of new lines to hand over per poll +# whatever the page size is. Reading a backlog wants a far larger chunk_size. +DEFAULT_LOG_CHUNK_LINES = 10 # The server re-delivers a ~15s look-behind window on fetch-newer requests; only the # caller's events within this generous margin of the boundary can be re-delivered. LOG_DEDUP_RETENTION_MS = 300_000 # The log read path is rate limited upstream on a bucket shared by every caller, and the -# API reports a saturated bucket the same way it reports a sick store: HTTP 503. Doubling -# from half a second spends about seven seconds over the budget below — long enough to -# outlast a bucket refill without looking hung. +# API reports a saturated bucket the same way it reports a sick store: HTTP 503. LOG_BUSY_STATUS = 503 +# Doubling from half a second spends about seven seconds over these attempts — long enough +# to outlast a bucket refill without looking hung. LOG_RETRY_ATTEMPTS = 5 LOG_RETRY_BASE_SECONDS = 0.5 # Fraction of each backoff to vary it by: the bucket is shared, so clients backing off in @@ -44,7 +49,7 @@ LOG_RETRY_JITTER = 0.25 -def _with_busy_retry(fetch_page): +def _with_busy_retry(fetch_page: Callable[[], list]) -> list: """Call fetch_page, retrying while the store reports itself busy. There is no server-issued cursor, so a page request is a pure function of its anchor and re-issuing it can neither duplicate nor skip lines.""" @@ -56,7 +61,7 @@ def _with_busy_retry(fetch_page): raise backoff = LOG_RETRY_BASE_SECONDS * 2**attempt time.sleep(backoff * (1 + random.uniform(-LOG_RETRY_JITTER, LOG_RETRY_JITTER))) - # the last attempt propagates whatever it raises + # The last attempt propagates whatever it raises. return fetch_page() @@ -403,7 +408,7 @@ def fetch_logs( pod: str, start_time: Optional[int] = None, end_time: Optional[int] = None, - chunk_size: int = 10, + chunk_size: int = DEFAULT_LOG_CHUNK_LINES, ) -> Iterator[List[DeploymentLogEvent]]: """Fetch one pod's stored log lines within [start_time, end_time] (epoch ms, inclusive), yielded lazily oldest first as chunks of DeploymentLogEvent, @@ -484,8 +489,8 @@ def chunks() -> Iterator[List[DeploymentLogEvent]]: while True: anchor: Union[list, int] = _recent_anchor(held) if held else initial_boundary page = _with_busy_retry( - lambda anchor=anchor: self._fetch_log_page( - deployment_id, revision_number, pod, after=anchor, max_lines=chunk_size + partial( + self._fetch_log_page, deployment_id, revision_number, pod, after=anchor, max_lines=chunk_size ) ) past_end = False diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index 442bb7c..5bda265 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -13,7 +13,7 @@ def format_event(event) -> str: ts = datetime.fromtimestamp(event.timestamp / 1000, tz=timezone.utc).isoformat() - return f"[{ts}] {event.pod} {event.message}" + return f"[{ts}] {event.message}" def main(): @@ -28,10 +28,10 @@ def main(): # A window read: start_time/end_time are epoch ms, inclusive. With end_time # set the iterator terminates once the window is delivered or the store has - # no more lines to give. fetch_logs is lazy — each server page is yielded as - # one chunk, and only a short dedup window is held however large the read. - # chunk_size is also the number of lines requested per round trip, so a bulk - # read wants a large value. + # no more lines to give. fetch_logs is lazy — each server page that carries + # window lines is yielded as one chunk, and only a short dedup window is held + # however large the read. chunk_size is also the number of lines requested per + # round trip, so a bulk read wants a large value. now_ms = int(time.time() * 1000) print(f"Last {WINDOW_MINUTES} minutes of pod {pod}:\n") count = 0 diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index fc8174a..c7127d7 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -17,8 +17,6 @@ from centml.sdk.api import ( LOG_DEDUP_RETENTION_MS, LOG_RETRY_ATTEMPTS, - LOG_RETRY_BASE_SECONDS, - LOG_RETRY_JITTER, MAX_LOG_PAGE_LINES, CentMLClient, DeploymentLogSession, @@ -1061,9 +1059,9 @@ def test_fetch_logs_backs_off_further_on_each_busy_answer(): waited = [call.args[0] for call in sleep.call_args_list] assert len(waited) == LOG_RETRY_ATTEMPTS - 1 - for attempt, seconds in enumerate(waited): - nominal = LOG_RETRY_BASE_SECONDS * 2**attempt - assert nominal * (1 - LOG_RETRY_JITTER) <= seconds <= nominal * (1 + LOG_RETRY_JITTER) + # Each wait is longer than the one before it, so a store that stays busy is asked + # less and less often rather than hammered at a fixed interval. + assert all(earlier < later for earlier, later in zip(waited, waited[1:])) def test_fetch_logs_does_not_retry_a_request_the_store_rejects(): From 93ea7a2e4afb197a21ebd57f0157b7543aa9ff12 Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 16:23:05 -0400 Subject: [PATCH 21/22] Pin that the busy-page backoff grows geometrically MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Strictly increasing waits let a regression to a fixed interval through whenever four jittered samples happen to land in ascending order — about one run in twenty-four. Comparing the last wait against the first closes that: doubling clears the margin every time, a fixed interval never does. Signed-off-by: Honglin Cao --- tests/test_sdk_api.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/tests/test_sdk_api.py b/tests/test_sdk_api.py index c7127d7..11d8ae1 100644 --- a/tests/test_sdk_api.py +++ b/tests/test_sdk_api.py @@ -1060,8 +1060,11 @@ def test_fetch_logs_backs_off_further_on_each_busy_answer(): waited = [call.args[0] for call in sleep.call_args_list] assert len(waited) == LOG_RETRY_ATTEMPTS - 1 # Each wait is longer than the one before it, so a store that stays busy is asked - # less and less often rather than hammered at a fixed interval. + # less and less often rather than hammered at a fixed interval. The last wait also + # dwarfs the first: a fixed interval, however jittered, could not span that, while + # doubling across these attempts clears it with room to spare. assert all(earlier < later for earlier, later in zip(waited, waited[1:])) + assert waited[-1] > waited[0] * 4 def test_fetch_logs_does_not_retry_a_request_the_store_rejects(): From 1fc73ac6b67d2df6052e4cd03011e56cd039a53c Mon Sep 17 00:00:00 2001 From: Honglin Cao Date: Wed, 16 Sep 2026 17:17:36 -0400 Subject: [PATCH 22/22] Name the pods the example did not pick, and the shape it does not show MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Reading pods[0] without printing the roster hides from a multi-replica reader that there were other pods to choose from. Running the two demonstrated shapes back to back is also the one composition that loses lines: the tail begins at its own "now", so whatever was logged between the window's end_time and that moment belongs to neither read. Measured against the local environment: 16 lines written while the window read paged, 15 of them never delivered. One generator with an earlier start_time and no end_time covers both and has no such window — same test, nothing missing. Say so where someone is about to copy the wrong pair. Signed-off-by: Honglin Cao --- examples/sdk/get_deployment_logs.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/examples/sdk/get_deployment_logs.py b/examples/sdk/get_deployment_logs.py index 5bda265..ad56d74 100644 --- a/examples/sdk/get_deployment_logs.py +++ b/examples/sdk/get_deployment_logs.py @@ -25,6 +25,8 @@ def main(): return pod = pods[0] + # One call reads one pod, so here is the rest of the revision's roster. + print(f"Pods with logs: {', '.join(pods)}\n") # A window read: start_time/end_time are epoch ms, inclusive. With end_time # set the iterator terminates once the window is delivered or the store has @@ -52,6 +54,11 @@ def main(): # defaults to the moment of the call, and once caught up the generator # yields an empty chunk each time nothing new is stored yet — the caller # decides when to sleep or break. No line is ever delivered twice. + # + # Passing an earlier start_time here rather than omitting it delivers the + # backlog first and then follows, in one pass. That is the shape to reach + # for when both are wanted: a tail started after a separate window read + # begins at its own "now", losing whatever was logged in between. print(f"\nTailing pod {pod}; stopping after {TAIL_LINES} new lines...") printed = 0 for chunk in cclient.fetch_logs(DEPLOYMENT_ID, REVISION_NUMBER, pod):