runpod: a pod's log has to outlive the pod (v0.3.19)

A rented pod is the one machine in the system whose logs cannot be read. RunPod
publishes no pod-log API — its REST spec lists 23 routes and none serve logs,
which is why every attempt returns HTTP 400 — and boot.sh writes its phases to
a file and then execs uvicorn, whose output goes to the container's stdout and
nowhere else. /boot therefore covered the way up and nothing after it, and
_dump_pod_logs only ever ran on a failure, printing into the orchestrator's log.

That cost an evening. Three pods were investigated in one session and two were
already destroyed by the time there was a question to ask — one reclaimed by
RunPod mid-request, taking the only evidence with it — so "the serving hangs"
stayed a hypothesis for an hour. It was not hanging: a page took 807s, most of
it the weights download every pod repeats because global volumes are
console-only, and every client had given up at 180-300s.

So the pod keeps a bounded ring of its own stdout and stderr (codai/api/podlog)
and serves it at /logs with a cursor, and the pool drains that on every scaler
tick into <config_dir>/pod-logs/<pod_id>.log — kept AFTER the pod dies, which is
the whole point. It also drains once more before tearing a pod down, because the
interesting lines are the last ones and they are only readable while the pod
exists.

A pull, not a push: the orchestrator already reaches pods to serve requests, so
the bearer token and pinned TLS apply unchanged and a pod with no outbound route
still gets its log kept. Bounded at both ends, since neither disk is free, and a
gap in the pod's ring is written into the file instead of passing silently. The
stdout tee writes through to the real stream on every failure path — a logging
aid that could break printing would be worse than none.
Co-Authored-By: 's avatarClaude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PxYHWbCAjjjD7A1rhFKtaW
parent b2f91079
......@@ -16,7 +16,7 @@
# Canonical product version for CoderAI — single source of truth. Both the API
# metadata and the admin web UI read from here.
__version__ = "0.3.18"
__version__ = "0.3.19"
__tagline__ = "Complete orchestration, distribution and escalation of remotizable advanced inference."
# Configure the CUDA caching allocator BEFORE torch is imported anywhere.
......
......@@ -75,6 +75,13 @@ _BOOT_PHASES: list = []
_BOOT_T0 = time.time()
try: # before the first boot_phase() call
from codai.api.podlog import install as _install_podlog
_install_podlog()
except Exception:
pass # a logging aid must never stop a boot
def boot_phase(what: str) -> None:
"""Record and print one boot step, with seconds since process start.
......@@ -315,6 +322,23 @@ from fastapi.responses import FileResponse, Response as _FaviconResponse
_favicon_path = admin_static_dir / "favicon.ico"
@app.get("/logs", include_in_schema=False)
async def pod_logs(since: int = 0, limit: int = 2000):
"""This process's own output, from ``since`` onwards, with a cursor.
The missing half of ``/boot``: that covers the way up, this covers the life
after it. A rented pod is the one machine whose logs cannot be read from
outside — RunPod serves none — so it has to be able to say it itself, and
the renting install drains this into a file it keeps after the pod is gone.
Same guard as every other pod route: on a pod the bearer token is required
(CODERAI_API_TOKEN), so this is not a way to read an install's log without
one.
"""
from codai.api.podlog import tail
return {"ok": True, **tail(since=since, limit=limit)}
@app.get("/boot", include_in_schema=False)
async def boot_progress():
"""What this process did on the way up, with timings.
......
# CoderAI - OpenAI-compatible API server
# Copyright (C) 2026 Stefy Lanza <stefy@nexlab.net>
# GPLv3 - see the project LICENSE.
"""What a pod was doing, readable over HTTP and after it is dead.
A rented pod is the one machine in the system whose logs cannot be read. RunPod
publishes no pod-log API — the REST spec lists 23 routes and none of them serve
logs, which is why every attempt comes back HTTP 400 — so the console is the only
outside view, and it is a human surface. ``boot.sh`` writes its phases to a file
and then ``exec``s uvicorn, whose output goes to the container's stdout and
nowhere else. ``/boot`` therefore covers the way up and nothing after it.
That gap costs real time. Three pods were investigated tonight and two were
already gone by the time there was a question to ask: a pod reclaimed mid-request
took its evidence with it, and "the serving hangs" stayed a hypothesis for an
hour because the only machine that knew was unreachable and then absent.
So the pod keeps a bounded ring of its own output and serves it at ``/logs``
with a cursor, and the renting install drains that into a file it keeps AFTER the
pod dies (see ``RunpodPodPool._drain_pod_log``). A ring rather than a file
because a pod's disk is rented too, and bounded because this must never be a
reason a pod falls over.
"""
import collections
import io
import sys
import threading
#: Lines kept. At ~120 bytes a line this is a few megabytes, which is more than
#: any boot or inference failure needs and small enough to be free.
MAX_LINES = 20000
_lock = threading.Lock()
_lines: "collections.deque" = collections.deque(maxlen=MAX_LINES)
_seq = 0 # monotonic cursor; survives eviction from the ring
_installed = False
def record(line: str) -> None:
"""Add one line to the ring. Never raises — it is called from a write path."""
global _seq
try:
text = line.rstrip("\n")
if not text:
return
with _lock:
_seq += 1
_lines.append((_seq, text))
except Exception:
pass
class _Tee(io.TextIOBase):
"""Writes through to the real stream and keeps a copy in the ring.
Deliberately a thin wrapper: the process's stdout is how everything else in
coderai reports itself, and a logging aid that can break printing would be
worse than no logging aid at all. Every failure path falls back to the real
stream.
"""
def __init__(self, real):
self._real = real
self._buf = ""
# -- the parts anything printing actually uses ------------------------- #
def write(self, s):
try:
self._real.write(s)
except Exception:
pass
try:
self._buf += s
while "\n" in self._buf:
line, self._buf = self._buf.split("\n", 1)
record(line)
if len(self._buf) > 8192: # a writer that never newlines
record(self._buf)
self._buf = ""
except Exception:
self._buf = ""
return len(s)
def flush(self):
try:
self._real.flush()
except Exception:
pass
def isatty(self):
try:
return self._real.isatty()
except Exception:
return False
def fileno(self):
return self._real.fileno()
@property
def encoding(self):
return getattr(self._real, "encoding", "utf-8")
def writable(self):
return True
def install() -> bool:
"""Start copying this process's stdout and stderr into the ring.
Idempotent, and a no-op if the streams have no ``write`` (a frozen or
redirected environment). Returns whether it is now active.
"""
global _installed
with _lock:
if _installed:
return True
try:
sys.stdout = _Tee(sys.stdout)
sys.stderr = _Tee(sys.stderr)
except Exception:
return False
with _lock:
_installed = True
return True
def tail(since: int = 0, limit: int = 2000) -> dict:
"""Lines after ``since``, with the cursor to ask from next time.
``dropped`` says how many lines were evicted from the ring before the caller
got to them — silence and "nothing happened" must not look the same.
"""
with _lock:
rows = [(n, t) for (n, t) in _lines if n > int(since or 0)]
oldest = _lines[0][0] if _lines else 0
cursor = _seq
dropped = max(0, (oldest - 1) - int(since or 0)) if since and oldest else 0
if limit and len(rows) > limit:
rows = rows[-int(limit):]
return {"cursor": cursor, "dropped": dropped,
"lines": [t for (_n, t) in rows]}
......@@ -1868,6 +1868,8 @@ class PodHandle:
#: save money would be paying for the work twice.
draining: bool = False
console_url: str = ""
#: How far its /logs have been drained into our own file.
log_cursor: int = 0
#: Where this pod actually is and what it is. Reported to monitoring: the
#: region matters for latency and for where the data is allowed to live, and
#: "which model" is the first question anyone asks of a running fleet.
......@@ -2335,6 +2337,63 @@ class RunpodPodPool:
PORT_TIMEOUT_S = 900.0
HEALTH_TIMEOUT_S = 600.0
def _pod_log_path(self, pod_id: str) -> str:
"""Where this pod's drained log lives, beside the pod registry.
Kept after the pod is gone, which is the entire point: two of the three
pods investigated tonight had already been destroyed by the time there
was a question to ask.
"""
base = os.path.dirname(_pod_registry_path())
d = os.path.join(base, "pod-logs")
os.makedirs(d, exist_ok=True)
return os.path.join(d, f"{pod_id}.log")
def _drain_pod_log(self, pod: "PodHandle") -> None:
"""Copy whatever the pod has said since last time into our own file.
Pull rather than push: the orchestrator can already reach a pod (that is
how it serves requests), the auth and pinned TLS are already in place,
and a pod that cannot reach back out still gets its log kept. Bounded at
both ends — the pod keeps a ring, we keep a tail — because neither disk
is free.
"""
url = (pod.url or "").rstrip("/")
if not url:
return
since = getattr(pod, "log_cursor", 0) or 0
try:
headers = ({"Authorization": f"Bearer {self.api_key}"}
if self.api_key else {})
reply = pod_http.get(f"{url}/logs?since={since}&limit=2000",
headers=headers, timeout=15)
if reply.status_code != 200:
return # an older image has no /logs; nothing to do
data = reply.json()
except Exception:
return # unreachable is the health machinery's problem
lines = data.get("lines") or []
dropped = int(data.get("dropped") or 0)
pod.log_cursor = int(data.get("cursor") or since)
if not lines and not dropped:
return
path = self._pod_log_path(pod.pod_id)
try:
with open(path, "a") as fh:
if dropped:
# Silence and "nothing happened" must not read the same.
fh.write(f"[drain] {dropped} line(s) rolled out of the pod's "
f"ring before they were read\n")
for line in lines:
fh.write(line + "\n")
if os.path.getsize(path) > _POD_LOG_MAX_BYTES:
with open(path) as fh:
keep = fh.readlines()[-(_POD_LOG_KEEP_LINES):]
with open(path, "w") as fh:
fh.writelines(keep)
except OSError:
pass
def _dump_pod_logs(self, client, pod_id, why, url: str = ""):
"""Say what the pod was doing, from whichever source can still answer.
......@@ -2345,6 +2404,17 @@ class RunpodPodPool:
log, and it covers the container phases too (boot.sh writes them to the
same file). Tried first, because it is the only one that ever works.
"""
# Drain whatever it has said first, so the file we keep covers the
# failure itself and not merely everything up to the last tick.
try:
for p in list(self.pods):
if p.pod_id == pod_id:
self._drain_pod_log(p)
print(f"[runpod] pod {pod_id} log kept at "
f"{self._pod_log_path(pod_id)}", flush=True)
break
except Exception:
pass
if url:
try:
import requests
......@@ -3041,6 +3111,15 @@ class RunpodPodPool:
"""One scaler pass: shed pods the load no longer needs, reap idle/dead
ones to min_pods, keep min warm."""
now = time.time()
# Before anything is torn down: a pod's log is only readable while the
# pod exists, and the interesting lines are usually the last ones.
with self._cv:
alive_now = [p for p in self.pods if p.healthy]
for p in alive_now:
try:
self._drain_pod_log(p)
except Exception:
pass
self._scale_down(now)
with self._cv:
pods = list(self.pods)
......@@ -3717,6 +3796,11 @@ GLOBAL_VOLUME_MOUNT = "/workspace"
#: died between creating a pod and recording it).
REAP_GRACE_SECONDS = float(os.environ.get("CODERAI_RUNPOD_REAP_GRACE", "1200"))
#: Bounds on the kept-after-death pod log. Generous enough for a boot plus a
#: failure, small enough that a forgotten file cannot fill the config volume.
_POD_LOG_MAX_BYTES = int(os.environ.get("CODERAI_POD_LOG_MAX_BYTES", 8 * 1024 * 1024))
_POD_LOG_KEEP_LINES = int(os.environ.get("CODERAI_POD_LOG_KEEP_LINES", 20000))
def _pod_age_seconds(pod: dict):
"""Seconds since the pod was created, or None when RunPod does not say."""
......
......@@ -742,6 +742,33 @@ and the pool rents a second pod only once the first is carrying
`scale_up_inflight_per_pod` requests. The same `pool` field works on a burst
target, so two models' overflow shares one card.
### What a pod was doing
A rented pod is the one machine whose logs cannot be read from outside: RunPod
publishes no pod-log API (its REST spec lists 23 routes and none serve logs, so
every attempt returns HTTP 400), and `boot.sh` writes its phases to a file and
then execs uvicorn, whose output goes to the container's stdout and nowhere else.
So a coderai pod keeps a bounded ring of its own output and serves it:
```
GET /boot the way up: container phases + startup, with timings
GET /logs?since=<cursor> everything after it, with a cursor and a `dropped` count
```
and the renting install **drains** `/logs` on every scaler tick into
`<config_dir>/pod-logs/<pod_id>.log`, **which it keeps after the pod is gone**.
That is the point: a pod reclaimed mid-request takes its evidence with it, and
the file is what is left to read afterwards. Both ends are bounded
(`CODERAI_POD_LOG_MAX_BYTES`, `CODERAI_POD_LOG_KEEP_LINES`) because neither disk
is free, and a gap in the pod's ring is written into the file rather than passed
over in silence.
The drain is a pull, not a push: the orchestrator can already reach a pod — that
is how it serves requests — so the pod needs no outbound path, the bearer token
and pinned TLS already apply, and a pod with no route back out still gets its log
kept.
### Giving the pods back
Growth has a matching contraction. The pool asks how many pods the **current**
......
"""A pod's log has to outlive the pod.
A rented pod is the one machine in the system whose logs cannot be read from
outside: RunPod publishes no pod-log API (the REST spec lists 23 routes and none
of them serve logs, which is why every attempt returns HTTP 400), and `boot.sh`
writes its phases to a file and then execs uvicorn, whose output goes to the
container's stdout and nowhere else. So `/boot` covered the way up and nothing
after it.
That cost an evening. Three pods were investigated in one session and two were
already destroyed by the time there was a question to ask — one reclaimed by
RunPod mid-request, taking the only evidence with it — and "the serving hangs"
stayed a hypothesis for an hour because the machine that knew was first
unreachable and then absent. (It was not hanging: a page took 807s, mostly
weights download, and every client had given up at 180-300s.)
So the pod keeps a bounded ring of its own output and serves it with a cursor,
and the renting install drains that into a file it keeps AFTER the pod dies.
"""
import pathlib
import sys
ROOT = pathlib.Path(__file__).resolve().parents[1]
sys.path.insert(0, str(ROOT))
from codai.api import podlog # noqa: E402
from codai.api import runpod_worker as rw # noqa: E402
def _fresh():
podlog._lines.clear()
podlog._seq = 0
# ----------------------------------------------------------------- the ring #
def test_lines_come_back_with_a_cursor():
_fresh()
podlog.record("boot +0.1s container started")
podlog.record("vllm: loading weights")
out = podlog.tail()
assert out["lines"] == ["boot +0.1s container started", "vllm: loading weights"]
assert out["cursor"] == 2
def test_the_cursor_only_returns_what_is_new():
"""The drain runs every 15s; re-sending everything each time would make the
kept file mostly duplicates."""
_fresh()
podlog.record("one")
first = podlog.tail()
podlog.record("two")
second = podlog.tail(since=first["cursor"])
assert second["lines"] == ["two"]
def test_nothing_new_is_an_empty_answer_not_a_repeat():
_fresh()
podlog.record("one")
c = podlog.tail()["cursor"]
assert podlog.tail(since=c)["lines"] == []
def test_the_ring_is_bounded():
"""A pod's disk is rented too, and this must never be why one falls over."""
_fresh()
assert podlog._lines.maxlen == podlog.MAX_LINES
for i in range(podlog.MAX_LINES + 50):
podlog.record(f"line {i}")
assert len(podlog._lines) == podlog.MAX_LINES
def test_eviction_is_reported_rather_than_hidden():
"""Silence and "nothing happened" must not look the same: a caller that
fell behind needs to know its gap is a gap."""
_fresh()
podlog._lines.clear()
for i in range(5):
podlog.record(f"line {i}")
# Still holding everything: a caller at cursor 1 has missed nothing.
assert podlog.tail(since=1)["dropped"] == 0
# Now roll lines 2 and 3 out from under that caller: a real gap.
podlog._lines.popleft() # seq 1, already seen
podlog._lines.popleft() # seq 2, never seen
podlog._lines.popleft() # seq 3, never seen
out = podlog.tail(since=1)
assert out["dropped"] == 2
assert out["lines"] == ["line 3", "line 4"]
def test_blank_lines_are_not_recorded():
_fresh()
podlog.record("")
podlog.record("\n")
assert podlog.tail()["lines"] == []
# ------------------------------------------------- capturing without breaking #
def test_the_tee_writes_through_to_the_real_stream():
"""Printing is how everything else in coderai reports itself. A logging aid
that can break it would be worse than none."""
import io as _io
_fresh()
real = _io.StringIO()
tee = podlog._Tee(real)
tee.write("hello\n")
assert real.getvalue() == "hello\n"
assert podlog.tail()["lines"] == ["hello"]
def test_a_broken_real_stream_does_not_raise():
_fresh()
class _Broken:
def write(self, s):
raise OSError("stream closed")
def flush(self):
raise OSError("stream closed")
tee = podlog._Tee(_Broken())
tee.write("still recorded\n") # must not raise
tee.flush()
assert podlog.tail()["lines"] == ["still recorded"]
def test_a_writer_that_never_sends_a_newline_is_still_captured():
import io as _io
_fresh()
tee = podlog._Tee(_io.StringIO())
tee.write("x" * 9000)
assert podlog.tail()["lines"]
def test_install_is_idempotent():
assert podlog.install() in (True, False)
before = podlog._installed
podlog.install()
assert podlog._installed == before
# ------------------------------------------------------------- the drain side #
class _Reply:
def __init__(self, payload, status=200):
self._p, self.status_code = payload, status
def json(self):
return self._p
def _pool(tmp_path, monkeypatch, reply):
import threading
pool = rw.RunpodPodPool.__new__(rw.RunpodPodPool)
pool._cv = threading.Condition()
pool.model_key = "m"
pool.api_key = "tok"
pool.pods = []
monkeypatch.setattr(rw, "_pod_registry_path",
lambda: str(tmp_path / "runpod-pods.json"))
seen = {}
def _get(url, headers=None, timeout=None, **kw):
seen["url"] = url
seen["headers"] = headers or {}
return reply
from codai.api import pod_http
monkeypatch.setattr(pod_http, "get", _get)
return pool, seen
def _pod(pid="p1", url="https://10.0.0.2:8000", cursor=0):
return rw.PodHandle(pod_id=pid, url=url, hourly_usd=0.6, started_at=0.0,
log_cursor=cursor)
def test_the_drain_writes_a_file_named_for_the_pod(tmp_path, monkeypatch):
pool, _ = _pool(tmp_path, monkeypatch,
_Reply({"cursor": 2, "lines": ["a", "b"]}))
pod = _pod()
pool._drain_pod_log(pod)
kept = pathlib.Path(pool._pod_log_path("p1"))
assert kept.read_text().splitlines() == ["a", "b"]
def test_it_asks_only_for_what_it_has_not_seen(tmp_path, monkeypatch):
pool, seen = _pool(tmp_path, monkeypatch, _Reply({"cursor": 9, "lines": []}))
pool._drain_pod_log(_pod(cursor=7))
assert "since=7" in seen["url"]
def test_the_cursor_advances_so_the_file_does_not_repeat(tmp_path, monkeypatch):
pool, _ = _pool(tmp_path, monkeypatch,
_Reply({"cursor": 5, "lines": ["x"]}))
pod = _pod()
pool._drain_pod_log(pod)
assert pod.log_cursor == 5
def test_the_pods_bearer_token_is_sent(tmp_path, monkeypatch):
"""A pod is bearer-locked; an unauthenticated drain would get nothing."""
pool, seen = _pool(tmp_path, monkeypatch, _Reply({"cursor": 1, "lines": ["a"]}))
pool._drain_pod_log(_pod())
assert seen["headers"]["Authorization"] == "Bearer tok"
def test_an_older_image_without_logs_is_not_an_error(tmp_path, monkeypatch):
"""A pod built before this exists answers 404; the drain must shrug."""
pool, _ = _pool(tmp_path, monkeypatch, _Reply({}, status=404))
pod = _pod()
pool._drain_pod_log(pod) # must not raise
assert not pathlib.Path(pool._pod_log_path("p1")).exists()
def test_an_unreachable_pod_is_not_the_drains_problem(tmp_path, monkeypatch):
from codai.api import pod_http
pool, _ = _pool(tmp_path, monkeypatch, _Reply({}))
def _boom(*a, **kw):
raise OSError("connection refused")
monkeypatch.setattr(pod_http, "get", _boom)
pool._drain_pod_log(_pod()) # the health machinery owns that
def test_a_gap_in_the_pods_ring_is_written_into_the_file(tmp_path, monkeypatch):
pool, _ = _pool(tmp_path, monkeypatch,
_Reply({"cursor": 99, "dropped": 7, "lines": ["after"]}))
pool._drain_pod_log(_pod(cursor=1))
text = pathlib.Path(pool._pod_log_path("p1")).read_text()
assert "7 line(s) rolled out" in text and "after" in text
def test_the_kept_file_is_trimmed_rather_than_growing_for_ever(tmp_path,
monkeypatch):
pool, _ = _pool(tmp_path, monkeypatch, _Reply({"cursor": 1, "lines": ["z"]}))
monkeypatch.setattr(rw, "_POD_LOG_MAX_BYTES", 100)
monkeypatch.setattr(rw, "_POD_LOG_KEEP_LINES", 3)
path = pathlib.Path(pool._pod_log_path("p1"))
path.write_text("old\n" * 200)
pool._drain_pod_log(_pod())
assert len(path.read_text().splitlines()) <= 4
def test_the_file_survives_the_pod(tmp_path, monkeypatch):
"""The whole point. A pod reclaimed mid-request took its evidence with it;
the file is what is left to read afterwards."""
pool, _ = _pool(tmp_path, monkeypatch,
_Reply({"cursor": 3, "lines": ["last words"]}))
pod = _pod()
pool.pods.append(pod)
pool._drain_pod_log(pod)
pool.pods.clear() # pod gone
assert "last words" in pathlib.Path(pool._pod_log_path("p1")).read_text()
def test_maintenance_drains_before_it_tears_anything_down():
"""The interesting lines are the last ones, and they are only readable while
the pod still exists."""
import inspect
src = inspect.getsource(rw.RunpodPodPool.maintain)
assert "_drain_pod_log" in src
assert src.index("_drain_pod_log") < src.index("_scale_down")
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment