feat(host-agent): collect container logs (incremental push, byte-capped) [M79 step 1]
Agent-side of Docker container-log collection (milestone 79). Each interval the agent fetches new log lines per running container over the local Docker socket, demuxes the multiplexed stream, and folds sample["docker_logs"] into the same push as metrics — no inbound channel needed. - since-cursor per container kept in rate-state; a container's first interval seeds from a short tail, then fetches incrementally via ?since=<cursor> - _docker_request_raw + _demux_docker_logs + RFC3339Nano ts parsing (stdlib, TTY/unframed fallback); one row per (stream, ts, line) - per-batch byte cap with a truncation marker; logs are dropped (never buffered) across a backoff so an outage keeps metrics but not stale logs - docker_logs_enabled (default on) + docker_log_exclude per-host config keys - AGENT_VERSION 1.6.0 -> 1.7.0 Server ignores the new sample key until the ingest step lands, so this commit is CI-safe on its own. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01CAGR73DUowdVFVvYzLXC5C
This commit is contained in:
@@ -401,3 +401,190 @@ def test_read_config_honours_explicit_docker_socket(tmp_path):
|
||||
"docker_socket = /run/user/1000/docker.sock\n")
|
||||
cfg = a.read_config(str(cfg_file))
|
||||
assert cfg["docker_socket"] == "/run/user/1000/docker.sock"
|
||||
|
||||
|
||||
# ── container logs (m79) ──────────────────────────────────────────────────────
|
||||
|
||||
def _frame(stream: int, payload: bytes) -> bytes:
|
||||
"""Build one Docker multiplexed-log frame (8-byte header + payload)."""
|
||||
return bytes([stream, 0, 0, 0]) + len(payload).to_bytes(4, "big") + payload
|
||||
|
||||
|
||||
def test_demux_docker_logs_framed():
|
||||
raw = _frame(1, b"out line\n") + _frame(2, b"err line\n")
|
||||
assert a._demux_docker_logs(raw) == [
|
||||
("stdout", b"out line\n"), ("stderr", b"err line\n")]
|
||||
|
||||
|
||||
def test_demux_docker_logs_tty_fallback():
|
||||
# A TTY container's stream isn't framed — the leading byte ('2') is not a
|
||||
# valid stream id, so the whole blob is treated as one stdout payload.
|
||||
raw = b"2023-11-14T12:00:00.000000000Z hi\n"
|
||||
assert a._demux_docker_logs(raw) == [("stdout", raw)]
|
||||
|
||||
|
||||
def test_demux_docker_logs_empty():
|
||||
assert a._demux_docker_logs(b"") == []
|
||||
|
||||
|
||||
def test_parse_log_ts_handles_nanoseconds_and_z():
|
||||
dt = a._parse_log_ts("2023-11-14T12:00:00.123456789Z")
|
||||
assert dt is not None
|
||||
assert dt.year == 2023 and dt.microsecond == 123456 # ns trimmed to µs
|
||||
assert dt.utcoffset().total_seconds() == 0
|
||||
assert a._parse_log_ts("not-a-time") is None
|
||||
assert a._parse_log_ts("") is None
|
||||
|
||||
|
||||
def test_parse_container_logs_splits_streams_and_ts():
|
||||
raw = (_frame(1, b"2023-11-14T12:00:00.000000001Z hello world\n")
|
||||
+ _frame(2, b"2023-11-14T12:00:01.000000000Z oops\n"))
|
||||
parsed = a._parse_container_logs(raw)
|
||||
assert len(parsed) == 2
|
||||
dt0, s0, l0 = parsed[0]
|
||||
dt1, s1, l1 = parsed[1]
|
||||
assert (s0, l0) == ("stdout", "hello world")
|
||||
assert (s1, l1) == ("stderr", "oops")
|
||||
assert dt1 > dt0
|
||||
|
||||
|
||||
def test_parse_container_logs_keeps_unparseable_line():
|
||||
# No timestamp prefix (e.g. a partial write) → dt is None, full line kept.
|
||||
parsed = a._parse_container_logs(_frame(1, b"no-timestamp-here\n"))
|
||||
assert parsed == [(None, "stdout", "no-timestamp-here")]
|
||||
|
||||
|
||||
def test_collect_docker_logs_since_cursor_and_dedup(monkeypatch):
|
||||
containers = [{"name": "web", "status": "running"}]
|
||||
calls = []
|
||||
t1 = "2023-11-14T12:00:00.000000000Z"
|
||||
t2 = "2023-11-14T12:00:01.000000000Z"
|
||||
t3 = "2023-11-14T12:00:02.000000000Z"
|
||||
|
||||
def fake_raw(socket_path, path, timeout=a.DOCKER_API_TIMEOUT):
|
||||
calls.append(path)
|
||||
if "tail=" in path: # first interval seeds from a tail
|
||||
return _frame(1, f"{t1} a\n".encode()) + _frame(1, f"{t2} b\n".encode())
|
||||
# second interval: daemon re-returns the boundary line (t2) + a new one
|
||||
return _frame(1, f"{t2} b\n".encode()) + _frame(1, f"{t3} c\n".encode())
|
||||
|
||||
monkeypatch.setattr(a, "_docker_request_raw", fake_raw)
|
||||
state: dict = {}
|
||||
first = a.collect_docker_logs("/sock", containers, state)
|
||||
assert [r["line"] for r in first] == ["a", "b"]
|
||||
assert "tail=" in calls[0]
|
||||
|
||||
second = a.collect_docker_logs("/sock", containers, state)
|
||||
# boundary line b (t2) deduped against the cursor; only c (t3) is new
|
||||
assert [r["line"] for r in second] == ["c"]
|
||||
assert "since=" in calls[1]
|
||||
|
||||
|
||||
def test_collect_docker_logs_excludes_and_skips_non_running(monkeypatch):
|
||||
containers = [
|
||||
{"name": "web", "status": "running"},
|
||||
{"name": "noisy", "status": "running"},
|
||||
{"name": "db", "status": "exited"},
|
||||
]
|
||||
seen = []
|
||||
|
||||
def fake_raw(socket_path, path, timeout=a.DOCKER_API_TIMEOUT):
|
||||
seen.append(path)
|
||||
return _frame(1, b"2023-11-14T12:00:00.000000000Z x\n")
|
||||
|
||||
monkeypatch.setattr(a, "_docker_request_raw", fake_raw)
|
||||
out = a.collect_docker_logs("/sock", containers, {}, exclude=["noisy"])
|
||||
# only web is fetched: noisy is excluded, db isn't running
|
||||
assert seen and all("/containers/web/" in p for p in seen)
|
||||
assert {r["container"] for r in out} == {"web"}
|
||||
|
||||
|
||||
def test_collect_docker_logs_byte_cap_truncates(monkeypatch):
|
||||
containers = [{"name": "web", "status": "running"}]
|
||||
blob = b"".join(
|
||||
_frame(1, f"2023-11-14T12:00:{i:02d}.000000000Z {'x' * 20}\n".encode())
|
||||
for i in range(10))
|
||||
monkeypatch.setattr(a, "_docker_request_raw",
|
||||
lambda s, p, timeout=a.DOCKER_API_TIMEOUT: blob)
|
||||
out = a.collect_docker_logs("/sock", containers, {}, max_bytes=50)
|
||||
# Once the cap is crossed a single marker line is appended and we stop.
|
||||
assert out[-1]["container"] == "_steward"
|
||||
assert "truncated" in out[-1]["line"]
|
||||
real = [r for r in out if r["container"] == "web"]
|
||||
assert 0 < len(real) < 10
|
||||
|
||||
|
||||
def test_collect_docker_logs_forgets_gone_container_cursors(monkeypatch):
|
||||
monkeypatch.setattr(
|
||||
a, "_docker_request_raw",
|
||||
lambda s, p, timeout=a.DOCKER_API_TIMEOUT:
|
||||
_frame(1, b"2023-11-14T12:00:00.000000000Z x\n"))
|
||||
state: dict = {}
|
||||
a.collect_docker_logs("/sock", [{"name": "web", "status": "running"}], state)
|
||||
assert "web" in state["docker_log_cursors"]
|
||||
# web is gone next interval → its cursor is pruned so state can't grow forever
|
||||
a.collect_docker_logs("/sock", [{"name": "db", "status": "running"}], state)
|
||||
assert "web" not in state["docker_log_cursors"]
|
||||
assert "db" in state["docker_log_cursors"]
|
||||
|
||||
|
||||
def test_build_sample_includes_logs_when_present(monkeypatch):
|
||||
monkeypatch.setattr(a, "collect_docker",
|
||||
lambda _s: [{"name": "web", "status": "running"}])
|
||||
monkeypatch.setattr(a, "collect_swarm", lambda _s: None)
|
||||
monkeypatch.setattr(a, "collect_disk_usage", lambda _s: None)
|
||||
monkeypatch.setattr(
|
||||
a, "collect_docker_logs",
|
||||
lambda *args, **kw: [{"container": "web", "stream": "stdout",
|
||||
"ts": "t", "line": "hello"}])
|
||||
sample = a.build_sample(["/"], {}, "/var/run/docker.sock")
|
||||
assert sample["docker_logs"][0]["line"] == "hello"
|
||||
|
||||
|
||||
def test_build_sample_omits_logs_when_disabled(monkeypatch):
|
||||
monkeypatch.setattr(a, "collect_docker",
|
||||
lambda _s: [{"name": "web", "status": "running"}])
|
||||
monkeypatch.setattr(a, "collect_swarm", lambda _s: None)
|
||||
monkeypatch.setattr(a, "collect_disk_usage", lambda _s: None)
|
||||
called = {"logs": False}
|
||||
|
||||
def _logs(*args, **kw):
|
||||
called["logs"] = True
|
||||
return [{"container": "web", "line": "x"}]
|
||||
|
||||
monkeypatch.setattr(a, "collect_docker_logs", _logs)
|
||||
sample = a.build_sample(["/"], {}, "/var/run/docker.sock",
|
||||
docker_logs_enabled=False)
|
||||
assert "docker_logs" not in sample
|
||||
assert called["logs"] is False # collection skipped entirely, not just dropped
|
||||
|
||||
|
||||
def test_drop_logs_strips_only_logs():
|
||||
sample = {"ts": "t", "cpu_pct": 5.0,
|
||||
"docker": [{"name": "web"}], "docker_logs": [{"line": "x"}]}
|
||||
out = a._drop_logs(sample)
|
||||
assert "docker_logs" not in out
|
||||
assert out["docker"] == [{"name": "web"}] and out["cpu_pct"] == 5.0 # metrics kept
|
||||
assert a._drop_logs(out) is out # idempotent
|
||||
|
||||
|
||||
def test_read_config_docker_logs_default_on(tmp_path):
|
||||
p = tmp_path / "agent.conf"
|
||||
p.write_text("url = x\ntoken = y\n")
|
||||
cfg = a.read_config(str(p))
|
||||
assert cfg["docker_logs_enabled"] is True
|
||||
assert cfg["docker_log_exclude"] == []
|
||||
|
||||
|
||||
def test_read_config_disables_docker_logs(tmp_path):
|
||||
p = tmp_path / "agent.conf"
|
||||
p.write_text("url = x\ntoken = y\ndocker_logs_enabled = false\n")
|
||||
cfg = a.read_config(str(p))
|
||||
assert cfg["docker_logs_enabled"] is False
|
||||
|
||||
|
||||
def test_read_config_parses_docker_log_exclude(tmp_path):
|
||||
p = tmp_path / "agent.conf"
|
||||
p.write_text("url = x\ntoken = y\ndocker_log_exclude = watchtower, foo\n")
|
||||
cfg = a.read_config(str(p))
|
||||
assert cfg["docker_log_exclude"] == ["watchtower", "foo"]
|
||||
|
||||
Reference in New Issue
Block a user