feat(host_agent): agent 1.10 — backoff inside the stale window, posts of five, a deadline on Docker, /system/df every ten minutes (#5154)

- BACKOFF_CAP 300 → 60: Steward reads a host stale after 180 s, so an agent
  backing off to five minutes read stopped long after Steward came back
  (lesson #4355: a check-in inherits its call's backoff).
- A POST carries at most five samples: the oldest four buffered plus the
  new one, the rest held for the next post. A backlog drains a few at a
  time instead of in one post Steward cannot write before the timeout
  (the loop measured in #5149).
- Per-container Docker work has a 20 s deadline over the whole fan-out.
  Past it the sample reports docker_status "error" ("N of M containers
  not read within 20 s") and no list: a partial list would read as
  removals, and a record without its inspect as restarts.
- /system/df is asked every 600 s rather than every sample; Steward keeps
  the last answer.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

plugins/host_agent/agent.py

@@ -17,10 +17,10 @@ import time
 import urllib.error
 import urllib.request
 from collections import deque
-from concurrent.futures import ThreadPoolExecutor
+from concurrent.futures import ThreadPoolExecutor, wait as wait_futures
 from datetime import datetime, timezone
 
-AGENT_VERSION = "1.9.0"
+AGENT_VERSION = "1.10.0"
 
 # Default path to the local Docker Engine socket. Overridable via the
 # `docker_socket` config key; collection is silently skipped if it's absent or
@@ -440,6 +440,13 @@ def _rates(cur: dict, prev: dict, dt: float) -> dict:
 # when that header is present rather than assume Content-Length.
 
 DOCKER_API_TIMEOUT = 5.0
+# All of one sample's per-container Docker work (inspect + stats) must finish
+# inside this; past it the sample says Docker did not answer in time rather
+# than holding up the host's own metrics (#5154).
+DOCKER_DEADLINE_SECONDS = 20.0
+# /system/df walks every image, container and volume: asked this often, not
+# every sample. Steward keeps the last answer between reports.
+DOCKER_DF_INTERVAL_SECONDS = 600.0
 
 # Container-log collection (m79). Logs ride in the same push as metrics, so one
 # interval's batch is capped to keep a chatty container from bloating a POST (and
@@ -718,9 +725,23 @@ def collect_docker(socket_path: str) -> tuple:
     # call blocks ~1s while the daemon computes the cpu delta. Done serially that
     # stretches the whole sample on a busy host, so fan the per-container work out
     # over a small bounded thread pool (I/O-bound → threads are enough).
-    workers = min(8, len(containers))
-    with ThreadPoolExecutor(max_workers=workers) as ex:
-        return "ok", None, list(ex.map(lambda c: _collect_one_container(socket_path, c), containers))
+    # A deadline on the whole fan-out: one wedged container must not stall the
+    # sample. Unfinished work is reported as Docker not answering in time, not
+    # as a partial list: a container left out would read as removed, and one
+    # without its inspect as restarted or changed health.
+    ex = ThreadPoolExecutor(max_workers=min(8, len(containers)))
+    try:
+        futures = [ex.submit(_collect_one_container, socket_path, c) for c in containers]
+        done, pending = wait_futures(futures, timeout=DOCKER_DEADLINE_SECONDS)
+    finally:
+        try:
+            ex.shutdown(wait=False, cancel_futures=True)
+        except TypeError:          # Python < 3.9: no cancel_futures
+            ex.shutdown(wait=False)
+    if pending:
+        return ("error", "%d of %d containers not read within %g s"
+                % (len(pending), len(containers), DOCKER_DEADLINE_SECONDS), [])
+    return "ok", None, [f.result() for f in futures]
 
 
 # ─── container logs (m79) ─────────────────────────────────────────────────────
@@ -1243,7 +1264,8 @@ def build_sample(mounts: list[str], state: dict,
 
     # Image/disk usage — host-level docker fact (one /system/df call), only
     # when Docker answered.
-    if docker_status == "ok":
+    if docker_status == "ok" and now_mono - state.get("df_mono", float("-inf")) >= DOCKER_DF_INTERVAL_SECONDS:
+        state["df_mono"] = now_mono
         try:
             disk = collect_disk_usage(docker_socket)
         except Exception:
@@ -1278,7 +1300,14 @@ def build_payload(samples: list[dict], hostname: str, metadata: dict) -> dict:
 # ─── POST + backoff ──────────────────────────────────────────────────────────
 
 
-BACKOFF_CAP = 300
+# Below Steward's 180 s staleness window (host_agent stale_after_seconds): once
+# Steward is reachable again a host reports within a minute, instead of reading
+# as stale for up to five (#5154; lesson: a check-in inherits its call's backoff).
+BACKOFF_CAP = 60
+# Samples in one POST: the server writes at most this many (routes.py
+# MAX_SAMPLES_PER_INGEST), so a backlog drains a few per post, oldest first,
+# rather than in one post too big to write before the timeout.
+MAX_SAMPLES_PER_POST = 5
 
 
 def _drop_logs(sample: dict) -> dict:
@@ -1293,6 +1322,12 @@ def _drop_logs(sample: dict) -> dict:
     return sample
 
 
+def split_backlog(buffered: list, limit: int = MAX_SAMPLES_PER_POST) -> tuple:
+    """(the buffered samples to send with this one, the ones held for later):
+    the oldest limit-1, leaving room for the new sample."""
+    return buffered[:limit - 1], buffered[limit - 1:]
+
+
 def next_backoff(current: int) -> int:
     if current <= 0:
         return 30
@@ -1385,16 +1420,20 @@ def main_loop(conf_path: str) -> int:
                               docker_logs_enabled=docker_logs_enabled,
                               docker_log_exclude=docker_log_exclude)
         buffered = buffer.drain()
+        send, held = split_backlog(buffered)
         payload = build_payload(
-            samples=buffered + [sample],
+            samples=send + [sample],
             hostname=hostname,
             metadata=metadata,
         )
         ok, status = post_payload(cfg["url"], cfg["token"], payload)
 
         if ok:
-            if buffered:
-                _log("INFO", f"flushed {len(buffered)} buffered samples")
+            for s in held:
+                buffer.push(s)
+            if send:
+                _log("INFO", f"flushed {len(send)} buffered samples"
+                             + (f", {len(held)} still held" if held else ""))
             backoff = 0
             sleep_for = cfg["interval_seconds"]
         else:

tests/plugins/host_agent/test_agent_build_payload.py

@@ -113,11 +113,18 @@ def test_post_payload_network_error_returns_none_status():
     assert status is None
 
 
-def test_backoff_schedule():
+def test_backoff_schedule_stays_inside_the_stale_window():
     from plugins.host_agent.agent import next_backoff
     assert next_backoff(0) == 30
     assert next_backoff(30) == 60
-    assert next_backoff(60) == 120
-    assert next_backoff(120) == 240
-    assert next_backoff(240) == 300  # capped
-    assert next_backoff(300) == 300
+    assert next_backoff(60) == 60    # capped below Steward's 180 s stale window (#5154)
+
+
+def test_a_backlog_drains_a_few_samples_a_post_oldest_first():
+    from plugins.host_agent.agent import MAX_SAMPLES_PER_POST, split_backlog
+    buffered = list(range(20))
+    send, held = split_backlog(buffered)
+    assert send == [0, 1, 2, 3] and held == list(range(4, 20))
+    assert len(send) + 1 == MAX_SAMPLES_PER_POST    # room for the new sample
+    assert split_backlog([7]) == ([7], [])
+    assert split_backlog([]) == ([], [])

tests/plugins/host_agent/test_agent_docker.py

@@ -706,3 +706,39 @@ def test_read_config_parses_docker_log_exclude(tmp_path):
 ])
 def test_docker_started_at(insp, started):
     assert a._docker_started_at(insp) == started
+
+
+def test_collect_docker_past_its_deadline_says_so_and_lists_nothing(monkeypatch):
+    # A partial list would read as removals; a record without inspect as restarts.
+    import threading
+    release = threading.Event()
+
+    def one(socket_path, c):
+        if c["Names"] == ["/stuck"]:
+            release.wait(2)
+        return {"name": c["Names"][0].lstrip("/")}
+
+    listing = [{"Id": "a" * 16, "Names": ["/fine"]}, {"Id": "b" * 16, "Names": ["/stuck"]}]
+    monkeypatch.setattr(a, "_docker_request", lambda s, p, timeout=a.DOCKER_API_TIMEOUT: listing)
+    monkeypatch.setattr(a, "_collect_one_container", one)
+    monkeypatch.setattr(a, "DOCKER_DEADLINE_SECONDS", 0.05)
+    try:
+        assert a.collect_docker("/s") == ("error", "1 of 2 containers not read within 0.05 s", [])
+    finally:
+        release.set()
+
+
+def test_disk_usage_is_asked_on_its_own_cadence(monkeypatch):
+    calls = []
+    clock = {"t": 1000.0}
+    monkeypatch.setattr(a.time, "monotonic", lambda: clock["t"])
+    monkeypatch.setattr(a, "collect_docker", lambda _s: ("ok", None, []))
+    monkeypatch.setattr(a, "collect_swarm", lambda _s: (None, None))
+    monkeypatch.setattr(a, "collect_disk_usage", lambda _s: calls.append(clock["t"]) or {"images_total": 1})
+    state = {}
+    seen = []
+    for t in (1000.0, 1030.0, 1000.0 + a.DOCKER_DF_INTERVAL_SECONDS):
+        clock["t"] = t
+        seen.append("docker_disk" in a.build_sample(["/"], state, "/s"))
+    assert seen == [True, False, True]
+    assert calls == [1000.0, 1000.0 + a.DOCKER_DF_INTERVAL_SECONDS]