From 404341f03fb15ac00f7dd2aeecaf082c9236535e Mon Sep 17 00:00:00 2001 From: rdwr-egore Date: Mon, 12 Oct 2026 16:59:21 +0000 Subject: [PATCH 1/2] fix: rate-limit removed container event warnings and resolve by ID --- tests/test_event_missing.py | 46 +++++++++++++++++++++++++++++++++++++ watchdog.py | 25 ++++++++++++++++++-- 2 files changed, 69 insertions(+), 2 deletions(-) create mode 100644 tests/test_event_missing.py diff --git a/tests/test_event_missing.py b/tests/test_event_missing.py new file mode 100644 index 0000000..7c37711 --- /dev/null +++ b/tests/test_event_missing.py @@ -0,0 +1,46 @@ +import logging +import unittest +from types import SimpleNamespace +from unittest.mock import Mock, patch + +import docker +import watchdog + + +class MissingContainerEventTests(unittest.TestCase): + def make_subject(self): + monitor = object.__new__(watchdog.Watchdog) + monitor._excluded = set() + monitor.client = SimpleNamespace(containers=Mock()) + monitor.client.containers.get.side_effect = docker.errors.NotFound("removed") + return monitor + + def test_flood_logs_once_per_event_type_and_uses_id(self): + monitor = self.make_subject() + events = [] + for _ in range(55): + for action in ("health_status: unhealthy", "die"): + events.append({"Action": action, "Actor": {"ID": "old-instance-123", "Attributes": {"name": "health-demo", "exitCode": "2"}}}) + with self.assertLogs("watchdog", level="WARNING") as logs: + for event in events: + monitor._handle_event(event) + self.assertEqual(len(logs.output), 2) + self.assertEqual(monitor.client.containers.get.call_count, 110) + self.assertTrue(all(call.args[0] == "old-instance-123" for call in monitor.client.containers.get.call_args_list)) + + def test_different_instance_not_suppressed(self): + monitor = self.make_subject() + with self.assertLogs("watchdog", level="WARNING") as logs: + for cid in ("old-id", "new-id"): + monitor._handle_event({"Action": "die", "Actor": {"ID": cid, "Attributes": {"name": "same-name"}}}) + self.assertEqual(len(logs.output), 2) + + def test_legacy_event_falls_back_to_name(self): + monitor = self.make_subject() + with self.assertLogs("watchdog", level="WARNING"): + monitor._handle_event({"Action": "die", "Actor": {"Attributes": {"name": "old-service"}}}) + monitor.client.containers.get.assert_called_once_with("old-service") + + +if __name__ == "__main__": + unittest.main() diff --git a/watchdog.py b/watchdog.py index aab65fa..d4161c2 100644 --- a/watchdog.py +++ b/watchdog.py @@ -1406,10 +1406,31 @@ def _handle_event(self, event: dict) -> None: log.debug("Docker event: %s on %s", action, name) + # Docker events refer to a container *instance*, not a reusable name. + # A removed instance must never be attributed to a newly created one. + container_id = event.get("Actor", {}).get("ID") or event.get("id") try: - container = self.client.containers.get(name) + container = self.client.containers.get(container_id or name) except docker.errors.NotFound: - log.warning("Container %s not found for event %s", name, action) + # Docker can deliver die/health events after an ephemeral container + # has been removed. Report at most once per instance/action per + # minute, rather than flooding logs and configured syslog sinks. + if not hasattr(self, "_missing_event_last_log"): + self._missing_event_last_log = {} + now = time.monotonic() + key = (container_id or name, action) + last = self._missing_event_last_log.get(key, -float("inf")) + if now - last >= 60: + self._missing_event_last_log[key] = now + log.warning( + "Container %s (%s) already removed before %s event could be processed", + name, container_id or "unknown ID", action, + ) + if len(self._missing_event_last_log) > 1024: + self._missing_event_last_log = { + k: t for k, t in self._missing_event_last_log.items() + if now - t < 60 + } return if is_ignored_container_event(container, attributes, action, self._ignored_events): From 65293ce2a3819a969aeecc980ae8bfdbf5e5efc0 Mon Sep 17 00:00:00 2001 From: rdwr-egore Date: Tue, 13 Oct 2026 22:24:56 +0000 Subject: [PATCH 2/2] fix: align event state and bound missing container cache --- tests/test_event_missing.py | 64 ++++++++++++++++++++++++++++++++++++- watchdog.py | 55 +++++++++++++++++++------------ 2 files changed, 97 insertions(+), 22 deletions(-) diff --git a/tests/test_event_missing.py b/tests/test_event_missing.py index 7c37711..4be608e 100644 --- a/tests/test_event_missing.py +++ b/tests/test_event_missing.py @@ -11,6 +11,7 @@ class MissingContainerEventTests(unittest.TestCase): def make_subject(self): monitor = object.__new__(watchdog.Watchdog) monitor._excluded = set() + monitor._missing_events = {} monitor.client = SimpleNamespace(containers=Mock()) monitor.client.containers.get.side_effect = docker.errors.NotFound("removed") return monitor @@ -25,7 +26,7 @@ def test_flood_logs_once_per_event_type_and_uses_id(self): for event in events: monitor._handle_event(event) self.assertEqual(len(logs.output), 2) - self.assertEqual(monitor.client.containers.get.call_count, 110) + self.assertEqual(monitor.client.containers.get.call_count, 1) self.assertTrue(all(call.args[0] == "old-instance-123" for call in monitor.client.containers.get.call_args_list)) def test_different_instance_not_suppressed(self): @@ -42,5 +43,66 @@ def test_legacy_event_falls_back_to_name(self): monitor.client.containers.get.assert_called_once_with("old-service") + def test_expiry_retries_missing_container(self): + monitor = self.make_subject() + event = {"Action": "die", "Actor": {"ID": "expired-id", "Attributes": {"name": "expired"}}} + with patch("watchdog.time.monotonic", side_effect=[100, 101, 161]): + with self.assertLogs("watchdog", level="WARNING") as logs: + for _ in range(3): + monitor._handle_event(event) + self.assertEqual(monitor.client.containers.get.call_count, 2) + self.assertEqual(len(logs.output), 2) + + def test_cache_bounded_during_high_churn(self): + monitor = self.make_subject() + with patch("watchdog.time.monotonic", return_value=100): + with patch("watchdog.log.warning"): + for n in range(1030): + monitor._handle_event({"Action": "die", "Actor": { + "ID": f"old-{n}", "Attributes": {"name": f"old-{n}"} + }}) + self.assertEqual(len(monitor._missing_events), 1024) + self.assertNotIn("old-0", monitor._missing_events) + monitor._handle_event({"Action": "die", "Actor": { + "ID": "old-0", "Attributes": {"name": "old-0"} + }}) + self.assertEqual(monitor.client.containers.get.call_count, 1031) + self.assertEqual(len(monitor._missing_events), 1024) + + def test_idless_legacy_name_is_reinspected(self): + monitor = self.make_subject() + event = {"Action": "die", "Actor": {"Attributes": {"name": "reusable-name"}}} + with self.assertLogs("watchdog", level="WARNING") as logs: + monitor._handle_event(event) + monitor._handle_event(event) + self.assertEqual(monitor.client.containers.get.call_count, 2) + self.assertEqual(len(logs.output), 1) + + def test_rename_and_name_reuse_records_old_container_not_new(self): + monitor = self.make_subject() + old = SimpleNamespace(name="service-old", attrs={"Config": {"Labels": {}}}) + monitor.client.containers.get.side_effect = None + monitor.client.containers.get.return_value = old + monitor._ignored_events = [] + monitor._discovered_checks = {} + monitor._oom_containers = set() + old_state = watchdog.ContainerState("service-old") + monitor.state = SimpleNamespace(get=Mock(return_value=old_state)) + monitor.host = "test" + monitor.runbook_base = "test" + monitor._claim_alert = Mock(return_value=True) + monitor._dispatch = Mock() + event = {"Action": "die", "Actor": {"ID": "old-id", "Attributes": { + "name": "service", "exitCode": "3" + }}} + with patch("watchdog.build_payload", return_value=object()): + monitor._handle_event(event) + monitor.client.containers.get.assert_called_once_with("old-id") + monitor.state.get.assert_called_once_with("service-old") + monitor._claim_alert.assert_called_once_with(old_state, "crashed") + monitor._dispatch.assert_called_once() + + + if __name__ == "__main__": unittest.main() diff --git a/watchdog.py b/watchdog.py index d4161c2..43c5dbe 100644 --- a/watchdog.py +++ b/watchdog.py @@ -1232,6 +1232,7 @@ def __init__(self, cfg: dict): self._ignored_events: list[dict] = cfg.get("ignored_container_events") or [] self._discovered_checks: dict[str, dict | None] = {} # auto-discovery cache self._oom_containers: set[str] = set() # suppress die alert when oom already fired + self._missing_events: dict[str, tuple[float, set[str]]] = {} self._auto_cfg: dict = cfg.get("auto_health_check", {}) _manual = cfg.get("container_health_checks") or {} self._manual_checks: dict = _manual if isinstance(_manual, dict) else {} @@ -1406,31 +1407,43 @@ def _handle_event(self, event: dict) -> None: log.debug("Docker event: %s on %s", action, name) - # Docker events refer to a container *instance*, not a reusable name. - # A removed instance must never be attributed to a newly created one. + # Keep recent missing IDs so late events do not repeatedly hit Docker. + # An ID-less legacy event must still be looked up: its name can be reused. container_id = event.get("Actor", {}).get("ID") or event.get("id") + cache_key = container_id or f"name:{name}" + now = time.monotonic() + missing = self._missing_events.get(cache_key) + if missing is not None and now - missing[0] >= 60: + self._missing_events.pop(cache_key) + missing = None + + if container_id and missing is not None: + if action not in missing[1]: + missing[1].add(action) + log.warning("Container %s (%s) already removed before %s event could be processed", + name, container_id, action) + return + try: container = self.client.containers.get(container_id or name) except docker.errors.NotFound: - # Docker can deliver die/health events after an ephemeral container - # has been removed. Report at most once per instance/action per - # minute, rather than flooding logs and configured syslog sinks. - if not hasattr(self, "_missing_event_last_log"): - self._missing_event_last_log = {} - now = time.monotonic() - key = (container_id or name, action) - last = self._missing_event_last_log.get(key, -float("inf")) - if now - last >= 60: - self._missing_event_last_log[key] = now - log.warning( - "Container %s (%s) already removed before %s event could be processed", - name, container_id or "unknown ID", action, - ) - if len(self._missing_event_last_log) > 1024: - self._missing_event_last_log = { - k: t for k, t in self._missing_event_last_log.items() - if now - t < 60 - } + if missing is None: + missing = (now, set()) + self._missing_events[cache_key] = missing + # Insertion-ordered dict: evict the oldest entry even during a burst. + if len(self._missing_events) > 1024: + self._missing_events.pop(next(iter(self._missing_events))) + if action not in missing[1]: + missing[1].add(action) + log.warning("Container %s (%s) already removed before %s event could be processed", + name, container_id or "unknown ID", action) + return + + # Events may carry the previous name of a renamed container. Incident + # tracking, recovery, OOM suppression, and probe caches use the name + # reported by the resolved container, consistent with the poll loop. + name = container.name + if name in self._excluded: return if is_ignored_container_event(container, attributes, action, self._ignored_events):