From 243d82aa74c42dab459a3e31bef7c814f5cec562 Mon Sep 17 00:00:00 2001 From: yxf Date: Sun, 20 Sep 2026 14:30:12 +0800 Subject: [PATCH] fix(deployer): read `since` as an absolute epoch on Kubernetes The abstract deployer declares `since` as an absolute epoch in seconds, and Docker and Podman implement it that way, but the Kubernetes implementation hands the value straight to sinceSeconds, which the API reads as a duration counted back from now. An epoch arrives as roughly 54 years, so the filter silently matches everything: a caller resuming a log stream from a cursor gets the whole log back instead, with no error to notice it by. Convert inside the deployer, rounding up and adding a second so the requested instant lands inside the window rather than just outside it, and keep the result positive -- a cursor ahead of the node's clock would otherwise produce a duration the API ignores. The same log paths also fail on their own declared default. `tail` defaults to None, and the two Kubernetes paths and both endoscopic ones compare it against zero before the API sees it, so a caller relying on the default gets a TypeError rather than every line. Fetching a workload's logs without a tail is exactly how a benchmark snapshot reads them. Task 2 of large-serving-logs. Signed-off-by: yxf --- gpustack_runtime/deployer/__init__.py | 8 +- gpustack_runtime/deployer/docker.py | 2 +- gpustack_runtime/deployer/kuberentes.py | 36 ++- gpustack_runtime/deployer/podman.py | 2 +- .../deployer/test_logs_options.py | 210 ++++++++++++++++++ 5 files changed, 247 insertions(+), 11 deletions(-) create mode 100644 tests/gpustack_runtime/deployer/test_logs_options.py diff --git a/gpustack_runtime/deployer/__init__.py b/gpustack_runtime/deployer/__init__.py index ed12fd8..1e72eca 100644 --- a/gpustack_runtime/deployer/__init__.py +++ b/gpustack_runtime/deployer/__init__.py @@ -245,7 +245,7 @@ def logs_workload( tail: The number of lines from the end of the logs to show. since: - Show logs since a given time (in seconds). + Show logs since the given epoch in seconds. follow: Whether to follow the logs. @@ -300,7 +300,7 @@ async def async_logs_workload( tail: The number of lines from the end of the logs to show. since: - Show logs since a given time (in seconds). + Show logs since the given epoch in seconds. follow: Whether to follow the logs. @@ -434,7 +434,7 @@ def logs_self( tail: The number of lines from the end of the logs to show. since: - Show logs since a given time (in seconds). + Show logs since the given epoch in seconds. follow: Whether to follow the logs. @@ -479,7 +479,7 @@ async def async_logs_self( tail: The number of lines from the end of the logs to show. since: - Show logs since a given time (in seconds). + Show logs since the given epoch in seconds. follow: Whether to follow the logs. diff --git a/gpustack_runtime/deployer/docker.py b/gpustack_runtime/deployer/docker.py index 71e43fb..2a70d89 100644 --- a/gpustack_runtime/deployer/docker.py +++ b/gpustack_runtime/deployer/docker.py @@ -2105,7 +2105,7 @@ def _endoscopic_logs( logs_options = { "timestamps": timestamps, - "tail": tail if tail >= 0 else None, + "tail": tail if tail is not None and tail >= 0 else None, "since": since, "follow": follow, } diff --git a/gpustack_runtime/deployer/kuberentes.py b/gpustack_runtime/deployer/kuberentes.py index fe85c2c..e84d206 100644 --- a/gpustack_runtime/deployer/kuberentes.py +++ b/gpustack_runtime/deployer/kuberentes.py @@ -3,8 +3,10 @@ import contextlib import json import logging +import math import os import re +import time from dataclasses import dataclass, field from datetime import datetime, timezone from decimal import Decimal @@ -710,6 +712,30 @@ def _resolve_privileged(container: Container, kdp: bool) -> bool: return True +def to_since_seconds(since: int | None) -> int | None: + """ + Convert an absolute epoch into the relative duration the Kubernetes API takes. + + Every deployer reads `since` as an absolute epoch in seconds, but the + Kubernetes client only exposes `sinceSeconds`, counted back from now. + Rounding up and adding a second keeps the requested instant inside the + window instead of just outside it; the caller sees a couple of seconds of + older lines rather than a gap. The result is always positive, as the API + ignores a zero or negative duration. + + Args: + since: + The absolute epoch in seconds, or None for no lower bound. + + Returns: + The relative duration in seconds, or None if since is None. + + """ + if since is None: + return None + return max(1, math.ceil(time.time() - since) + 1) + + class KubernetesDeployer(EndoscopicDeployer): """ Deployer implementation for Kubernetes. @@ -2439,7 +2465,7 @@ def _logs( tail: Number of lines from the end of the logs to retrieve. since: - Only return logs newer than a relative duration in seconds. + Show logs since the given epoch in seconds. follow: Whether to stream the logs. @@ -2477,8 +2503,8 @@ def _logs( logs_options = { "timestamps": timestamps, - "tail_lines": tail if tail >= 0 else None, - "since_seconds": since, + "tail_lines": tail if tail is not None and tail >= 0 else None, + "since_seconds": to_since_seconds(since), "follow": follow, "_preload_content": not follow, } @@ -2691,8 +2717,8 @@ def _endoscopic_logs( logs_options = { "timestamps": timestamps, - "tail_lines": tail if tail >= 0 else None, - "since_seconds": since, + "tail_lines": tail if tail is not None and tail >= 0 else None, + "since_seconds": to_since_seconds(since), "follow": follow, "_preload_content": not follow, } diff --git a/gpustack_runtime/deployer/podman.py b/gpustack_runtime/deployer/podman.py index 85cfdfa..16f88e4 100644 --- a/gpustack_runtime/deployer/podman.py +++ b/gpustack_runtime/deployer/podman.py @@ -2046,7 +2046,7 @@ def _endoscopic_logs( logs_options = { "timestamps": timestamps, - "tail": tail if tail >= 0 else None, + "tail": tail if tail is not None and tail >= 0 else None, "since": since, "follow": follow, } diff --git a/tests/gpustack_runtime/deployer/test_logs_options.py b/tests/gpustack_runtime/deployer/test_logs_options.py new file mode 100644 index 0000000..ddfe372 --- /dev/null +++ b/tests/gpustack_runtime/deployer/test_logs_options.py @@ -0,0 +1,210 @@ +# The cases below drive the deployers' own log path, which is where the log +# options become observable without a live Docker daemon, Podman socket or +# Kubernetes cluster. `since` is an absolute epoch in seconds for every +# deployer; only Kubernetes has to translate it, because its API takes a +# relative duration. `tail` has to survive its own declared default. +# ruff: noqa: SLF001 + +from types import SimpleNamespace + +import kubernetes.client +import pytest + +from gpustack_runtime.deployer.docker import ( + _LABEL_COMPONENT_INDEX as _DOCKER_LABEL_COMPONENT_INDEX, +) +from gpustack_runtime.deployer.docker import ( + DockerDeployer, +) +from gpustack_runtime.deployer.kuberentes import ( + KubernetesDeployer, + to_since_seconds, +) +from gpustack_runtime.deployer.podman import ( + _LABEL_COMPONENT_INDEX as _PODMAN_LABEL_COMPONENT_INDEX, +) +from gpustack_runtime.deployer.podman import ( + PodmanDeployer, +) + +_COMPONENT_INDEX_LABELS = { + DockerDeployer: _DOCKER_LABEL_COMPONENT_INDEX, + PodmanDeployer: _PODMAN_LABEL_COMPONENT_INDEX, +} + +NOW = 1_700_000_000 + + +@pytest.fixture +def frozen_now(monkeypatch): + monkeypatch.setattr( + "gpustack_runtime.deployer.kuberentes.time.time", + lambda: float(NOW), + ) + + +class _FakeCoreV1LogApi: + """ + Stand-in for the Kubernetes core API, recording the log calls it receives. + """ + + def __init__(self, journal: list): + self.journal = journal + + def __call__(self, client=None): + return self + + def read_namespaced_pod_log(self, **kwargs): + self.journal.append(kwargs) + return b"" + + +def _kubernetes_deployer(monkeypatch, journal: list) -> SimpleNamespace: + monkeypatch.setattr( + kubernetes.client, + "CoreV1Api", + _FakeCoreV1LogApi(journal), + ) + pod = kubernetes.client.V1Pod( + metadata=kubernetes.client.V1ObjectMeta(name="test", namespace="default"), + spec=kubernetes.client.V1PodSpec( + containers=[kubernetes.client.V1Container(name="run")], + ), + ) + return SimpleNamespace( + is_supported=lambda: True, + get=lambda **_kwargs: SimpleNamespace(_k_pod=pod), + _client=None, + _find_self_pod_for_endoscopy=lambda: pod, + ) + + +class _FakeContainer: + """ + Stand-in for a Docker or Podman container, recording its log calls. + """ + + def __init__(self, journal: list): + self.journal = journal + self.labels = {} + self.id = "cid" + self.short_id = "cid" + + def logs(self, **kwargs): + self.journal.append(kwargs) + return b"" + + +def _container_deployer(journal: list, deployer) -> SimpleNamespace: + container = _FakeContainer(journal) + # The component index label is how both deployers pick the loggable container. + container.labels = {_COMPONENT_INDEX_LABELS[deployer]: "0"} + return SimpleNamespace( + is_supported=lambda: True, + get=lambda **_kwargs: SimpleNamespace(_d_containers=[container]), + _find_self_container_for_endoscopy=lambda: container, + ) + + +@pytest.mark.parametrize( + "deployer", + [DockerDeployer, PodmanDeployer], +) +def test_container_logs_forward_the_epoch_verbatim(deployer): + # Docker and Podman both take an absolute epoch, so `since` passes through. + journal = [] + dep = _container_deployer(journal, deployer) + + deployer._logs(dep, name="test", tail=-1, since=NOW - 90) + + assert journal[0]["since"] == NOW - 90 + + +@pytest.mark.usefixtures("frozen_now") +def test_kubernetes_logs_convert_the_epoch_to_a_relative_duration(monkeypatch): + # The Kubernetes API counts back from now, so the same absolute epoch has to + # become a duration. Rounding up and adding a second keeps the requested + # instant inside the window rather than just outside it. + journal = [] + dep = _kubernetes_deployer(monkeypatch, journal) + + KubernetesDeployer._logs(dep, name="test", tail=-1, since=NOW - 90) + + assert journal[0]["since_seconds"] == 91 + + +@pytest.mark.usefixtures("frozen_now") +def test_kubernetes_endoscopic_logs_convert_the_epoch_too(monkeypatch): + # The deployer's own logs travel the same API and must not diverge. + journal = [] + dep = _kubernetes_deployer(monkeypatch, journal) + + KubernetesDeployer._endoscopic_logs(dep, tail=-1, since=NOW - 90) + + assert journal[0]["since_seconds"] == 91 + + +# Every way into the log path: each deployer serves both a workload and, in +# mirrored deployment, itself. +_ENTRY_POINTS = [ + (DockerDeployer, "_logs", {"name": "test"}), + (DockerDeployer, "_endoscopic_logs", {}), + (PodmanDeployer, "_logs", {"name": "test"}), + (PodmanDeployer, "_endoscopic_logs", {}), + (KubernetesDeployer, "_logs", {"name": "test"}), + (KubernetesDeployer, "_endoscopic_logs", {}), +] + + +def _entry_deployer(monkeypatch, journal: list, deployer) -> SimpleNamespace: + if deployer is KubernetesDeployer: + return _kubernetes_deployer(monkeypatch, journal) + return _container_deployer(journal, deployer) + + +@pytest.mark.parametrize("deployer, method, kwargs", _ENTRY_POINTS) +def test_an_unset_since_stays_unset(monkeypatch, deployer, method, kwargs): + # No lower bound must reach the API as no lower bound, not as "now". + journal = [] + dep = _entry_deployer(monkeypatch, journal, deployer) + + getattr(deployer, method)(dep, tail=-1, since=None, **kwargs) + + key = "since_seconds" if deployer is KubernetesDeployer else "since" + assert journal[0][key] is None + + +@pytest.mark.parametrize("deployer, method, kwargs", _ENTRY_POINTS) +def test_the_declared_tail_default_reaches_the_api( + monkeypatch, + deployer, + method, + kwargs, +): + # `tail` defaults to None, which has to mean "all lines" rather than blow up + # on a comparison against an integer. + journal = [] + dep = _entry_deployer(monkeypatch, journal, deployer) + + getattr(deployer, method)(dep, since=None, **kwargs) + + key = "tail_lines" if deployer is KubernetesDeployer else "tail" + assert journal[0][key] is None + + +@pytest.mark.parametrize( + "since, expected", + [ + # A whole minute back is a whole minute plus the safety second. + (NOW - 60, 61), + # The current second still has to ask for a positive duration. + (NOW, 1), + # A cursor ahead of the node's clock must not become a negative or zero + # duration, which the API rejects. + (NOW + 30, 1), + (None, None), + ], +) +@pytest.mark.usefixtures("frozen_now") +def test_to_since_seconds_never_returns_a_non_positive_duration(since, expected): + assert to_since_seconds(since) == expected