From 06b4119ad35e94783be3638720ea06106a537eca Mon Sep 17 00:00:00 2001 From: h Date: Sun, 20 Sep 2026 21:25:15 +0000 Subject: [PATCH] =?UTF-8?q?fix(hands,jobs):=20=D1=81=D1=83=D1=82=D0=BE?= =?UTF-8?q?=D1=87=D0=BD=D0=B0=D1=8F=20=D1=81=D0=B2=D0=BE=D0=B4=D0=BA=D0=B0?= =?UTF-8?q?=20=D1=83=D1=85=D0=BE=D0=B4=D0=B8=D1=82=20=D0=B8=20=D0=B2=20?= =?UTF-8?q?=D1=87=D0=B8=D1=81=D1=82=D1=8B=D0=B5=20=D1=81=D1=83=D1=82=D0=BA?= =?UTF-8?q?=D0=B8,=20=D0=BD=D0=BE=D1=80=D0=BC=D0=B0=20=D0=B2=D1=81=D0=BF?= =?UTF-8?q?=D0=BB=D0=B5=D1=81=D0=BA=D0=B0=20=D0=B7=D0=B0=D0=BC=D0=B8=D1=80?= =?UTF-8?q?=D0=B0=D0=B5=D1=82=20=D0=BD=D0=B0=20=D0=BC=D0=BE=D0=BB=D0=BE?= =?UTF-8?q?=D0=B4=D0=BE=D1=81=D1=82=D0=B8=20=D0=B1=D0=B5=D0=B4=D1=8B?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- beaver_agent/hands/komodo_logs.py | 165 +++++++++++++++++++++++------- tests/test_komodo_logs.py | 73 ++++++++++++- 2 files changed, 202 insertions(+), 36 deletions(-) diff --git a/beaver_agent/hands/komodo_logs.py b/beaver_agent/hands/komodo_logs.py index bc9ffc3..10e8203 100644 --- a/beaver_agent/hands/komodo_logs.py +++ b/beaver_agent/hands/komodo_logs.py @@ -9,7 +9,9 @@ Молчать - не то же самое, что забыть. Беда, идущая неделю, после первого доклада не исчезает: она переходит в длящиеся и раз в сутки идёт отдельной короткой сводкой (имена и числа, без строк), а если за проход её стало в разы -больше собственной нормы - снова дёргает сразу. Затихание наоборот: не тревога, +больше собственной нормы или просто больше потолка - снова дёргает сразу. +Сводка уходит и в лучшем случае, пустой: молчание что-то значит, только если +известно, что джоб жив и сколько проходов он сделал. Затихание наоборот: не тревога, а строка «стихло» с временем последнего события. Показанную строку лога чистит общий `security.redact` - тот же, что стоит на @@ -113,24 +115,44 @@ QUIET_AFTER = timedelta(hours=24) строка ещё лежит в хвосте. Иначе на тихом стеке «стихло» ждало бы неделями, пока строку не вытеснит.""" +PASSES_A_DAY = 8 +"""Сколько проходов должно случиться за сутки - ровно столько часов в кроне +(`40 1,4,7,10,13,16,19,22`). Сводка называет это число рядом с фактическим: +проходов меньше ожидаемого - значит, молчание в остальные часы ничего не +значило.""" + SURGE_FACTOR = 4.0 -"""Во сколько раз проход должен перебить собственную норму беды, чтобы снова -стоить тревоги. Проходов восемь в сутки, и счёт за проход сам по себе гуляет -вдвое (деплой, ночной крон, перезапуск) - вчетверо это уже не дрожание. -Считается по среднему за прошлые активные проходы, то есть у каждой беды -норма своя; хвост ограничен, поэтому взрыв упирается в TAIL и видно скорее -«стало на порядок», чем точную кратность.""" +"""Во сколько раз проход должен перебить норму беды, чтобы снова стоить +тревоги. Проходов восемь в сутки, и счёт за проход сам по себе гуляет вдвое +(деплой, ночной крон, перезапуск) - вчетверо это уже не дрожание. Хвост +ограничен, поэтому настоящий взрыв упирается в TAIL и видно скорее «стало на +порядок», чем точную кратность. Цифра из рассуждения, не из замера: +пересмотреть после первой недели живой работы.""" SURGE_MIN = 10 """Пол в штуках: без него «было одно, стало четыре» будило бы каждый раз.""" -SURGE_PASSES = 3 -"""Пока беду видели меньше трёх раз, нормы у неё нет и сравнивать не с чем.""" +SURGE_CEILING = 50 +"""Столько повторов одной строки за проход - новость сами по себе, без всякой +относительной нормы: медленно растущий отказ норму подтягивает за собой, и +кратность у него не срабатывает никогда. + +Отсчитано от живых чисел флота (20.09.2026): самый громкий ряд - +`personal-main-caddy` со 120 повторами в сутки на десять видов строк, это +~15 за проход на ряд; самая громкая отдельная строка - `coturn` с 38 в сутки, +то есть ~5 за проход. 50 - вдесятеро выше самой громкой строки и втрое выше +самого громкого ряда: известный фон под него не попадает, а настоящий взрыв +(~400 в сутки одной строкой) попадает. Тоже из рассуждения, а не из замера +взрыва - пересмотреть после первой недели.""" +NORM_PASSES = 3 +"""По скольким первым активным проходам берётся норма беды - и на этом она +замирает. Пересчитывать её дальше нельзя: отказ, растущий постепенно, тянет +свою норму за собой, и порог не срабатывает никогда - варёная лягушка.""" SURGE_HOLD = timedelta(hours=12) """Одна беда - не чаще раза в полсуток, даже если растёт ступенями.""" TREND_UP, TREND_DOWN = 1.5, 0.67 """Полтора раза в сутках - уже тренд, между ними - то же самое.""" KEY_CHARS = 12 -STATE_VERSION = 2 +STATE_VERSION = 3 EPOCH = datetime(1970, 1, 1, tzinfo=UTC) @@ -243,7 +265,10 @@ class Entry: count: int = 0 """Всего повторов, посчитанных приростом, а не перечитыванием хвоста.""" passes: int = 0 - """В скольких проходах она прирастала: по ним и считается её норма.""" + """В скольких проходах она прирастала.""" + norm: float = 0.0 + """Норма: среднее за первые ``NORM_PASSES`` активных проходов, дальше + заморожена. Считается по молодости беды, пока она ещё не разрослась.""" day_count: int = 0 day_before: int = 0 day_earlier: int = 0 @@ -262,11 +287,6 @@ class Entry: def where(self) -> str: return f"{self.stack}/{self.service}" - @property - def norm(self) -> float: - """Своя норма: сколько повторов у неё бывает за активный проход.""" - return self.count / self.passes if self.passes else 0.0 - @dataclass(frozen=True, slots=True) class Ongoing: @@ -315,9 +335,18 @@ class Report: ongoing: tuple[Entry, ...] = () """Длящееся: молчит в обычном проходе, идёт в суточную сводку.""" summary: bool = False - """Сутки закрылись и сводку по длящемуся ещё не отдавали.""" + """Сутки закрылись и сводку за них ещё не отдавали. Она уходит всегда - + и когда длящегося нет: молчание должно быть отличимо от мёртвого джоба.""" day: str = "" - """Сутки, за которые считается сводка (те, что только что закрылись).""" + """Закрывшиеся сутки: это про них все числа сводки.""" + today: str = "" + """Текущие сутки: ими помечается, что сводку уже отдали.""" + passes: int = 0 + """Проходов за закрывшиеся сутки - против ``PASSES_A_DAY`` ожидавшихся.""" + misses: int = 0 + """Чтений стеков, не удавшихся за те сутки.""" + blind: int = 0 + """Проходов тех суток, в которых Komodo не ответил вовсе.""" trouble: tuple[str, ...] = () gaps: tuple[str, ...] = () cold: bool = False @@ -346,8 +375,20 @@ class Seen: last_pass: datetime | None = None day: str | None = None """Локальные сутки, которым принадлежат суточные счётчики записей.""" + closed: str | None = None + """Последние закрывшиеся сутки: за них и отчитывается сводка.""" + passes_today: int = 0 + passes_before: int = 0 + """Сколько проходов случилось за текущие и за закрытые сутки: сводка + называет это число - иначе отвалившийся крон выглядит как чистый флот.""" + misses_today: int = 0 + misses_before: int = 0 + """Сколько чтений стеков не удалось за сутки.""" + blind_today: int = 0 + blind_before: int = 0 + """Сколько проходов за сутки Komodo не ответил вовсе.""" summary_day: str | None = None - """Сутки, за которые сводка по длящемуся уже доехала до мастера.""" + """Сутки, в которые сводка уже доехала до мастера.""" fresh: bool = True """Файла не было: базовую линию только снимаем, стену старых бед не шлём.""" @@ -371,6 +412,7 @@ class Seen: looked=_parse(row.get("looked")), count=int(row.get("count", 0)), passes=int(row.get("passes", 0)), + norm=float(row.get("norm", 0.0)), day_count=int(row.get("day_count", 0)), day_before=int(row.get("day_before", 0)), day_earlier=int(row.get("day_earlier", 0)), @@ -388,6 +430,13 @@ class Seen: trouble=tuple(raw.get("trouble", ())), last_pass=_parse(raw.get("last_pass")), day=raw.get("day"), + closed=raw.get("closed"), + passes_today=int(raw.get("passes_today", 0)), + passes_before=int(raw.get("passes_before", 0)), + misses_today=int(raw.get("misses_today", 0)), + misses_before=int(raw.get("misses_before", 0)), + blind_today=int(raw.get("blind_today", 0)), + blind_before=int(raw.get("blind_before", 0)), summary_day=raw.get("summary_day"), fresh=False, ) @@ -397,6 +446,13 @@ class Seen: "version": STATE_VERSION, "last_pass": _iso(self.last_pass), "day": self.day, + "closed": self.closed, + "passes_today": self.passes_today, + "passes_before": self.passes_before, + "misses_today": self.misses_today, + "misses_before": self.misses_before, + "blind_today": self.blind_today, + "blind_before": self.blind_before, "summary_day": self.summary_day, "baselined": sorted(self.baselined), "trouble": list(self.trouble), @@ -411,6 +467,7 @@ class Seen: "looked": _iso(e.looked), "count": e.count, "passes": e.passes, + "norm": e.norm, "day_count": e.day_count, "day_before": e.day_before, "day_earlier": e.day_earlier, @@ -443,8 +500,8 @@ class Seen: self.trouble = report.trouble def mark_daily(self, report: Report) -> None: - """Сводка доехала: за эти сутки больше не повторяем.""" - self.summary_day = report.day + """Сводка доехала: в эти сутки больше не повторяем.""" + self.summary_day = report.today def _iso(at: datetime | None) -> str | None: @@ -544,7 +601,7 @@ def _forget(seen: Seen, now: datetime) -> None: def _roll(seen: Seen, day: str) -> None: - """Сутки сменились: закрытый день уезжает в `day_before`, счёт с нуля.""" + """Сутки сменились: закрытый день уезжает в `*_before`, счёт с нуля.""" if seen.day == day: return if seen.day is not None: @@ -552,18 +609,31 @@ def _roll(seen: Seen, day: str) -> None: entry.day_earlier = entry.day_before entry.day_before = entry.day_count entry.day_count = 0 + seen.closed = seen.day + seen.passes_before, seen.passes_today = seen.passes_today, 0 + seen.misses_before, seen.misses_today = seen.misses_today, 0 + seen.blind_before, seen.blind_today = seen.blind_today, 0 seen.day = day def _surging(entry: Entry, gain: int, at: datetime) -> bool: - """Стал ли знакомый фон снова новостью: в разы выше собственной нормы.""" + """Стал ли знакомый фон снова новостью. + + Два независимых повода: в разы выше своей (замороженной) нормы или просто + выше потолка в штуках. Второй нужен ровно против того, что первый ловит + плохо, - беды, растущей так медленно, что норма растёт вместе с ней. + """ if not entry.told or entry.quieted is not None: return False - if entry.passes < SURGE_PASSES or gain < SURGE_MIN: + if entry.surged is not None and at - entry.surged <= SURGE_HOLD: return False - if gain < SURGE_FACTOR * entry.norm: - return False - return entry.surged is None or at - entry.surged > SURGE_HOLD + if gain >= SURGE_CEILING: + return True + return ( + entry.passes >= NORM_PASSES + and gain >= SURGE_MIN + and gain >= SURGE_FACTOR * entry.norm + ) def digest(seen: Seen, sweep: Sweep, tz: tzinfo = UTC) -> Report: @@ -572,6 +642,9 @@ def digest(seen: Seen, sweep: Sweep, tz: tzinfo = UTC) -> Report: _forget(seen, sweep.at) day = sweep.at.astimezone(tz).date().isoformat() _roll(seen, day) + seen.passes_today += 1 + seen.misses_today += max(sweep.in_scope - len(sweep.read), 0) + seen.blind_today += 1 if sweep.unreachable else 0 looked = {scan.stack for scan in sweep.read} newcomers = looked - seen.baselined hits = {hit.key: hit for scan in sweep.read for hit in scan.hits} @@ -611,6 +684,9 @@ def digest(seen: Seen, sweep: Sweep, tz: tzinfo = UTC) -> Report: entry.count += gain entry.passes += 1 entry.day_count += gain + if entry.passes <= NORM_PASSES: + # Норма берётся по молодости беды и дальше не трогается. + entry.norm = entry.count / entry.passes entry.last = hit.at or entry.last or sweep.at seen.baselined |= looked # Стихло - только про то, о чём говорили, и только у прочитанных стеков: @@ -649,8 +725,12 @@ def digest(seen: Seen, sweep: Sweep, tz: tzinfo = UTC) -> Report: surge=tuple(sorted(surge, key=lambda s: -s.gain)), quiet=tuple(sorted(quiet, key=lambda e: (e.stack, e.service))), ongoing=tuple(sorted(ongoing, key=lambda e: -e.day_before)), - summary=bool(ongoing) and seen.summary_day != day, - day=day, + summary=seen.closed is not None and seen.summary_day != day, + day=seen.closed or "", + today=day, + passes=seen.passes_before, + misses=seen.misses_before, + blind=seen.blind_before, trouble=trouble, gaps=gaps, cold=cold, @@ -742,19 +822,34 @@ def _daily_line(row: Ongoing, tz: tzinfo) -> str: def daily(report: Report, tz: tzinfo = UTC) -> str: - """Суточная сводка по длящемуся: имена и числа, без строк лога. + """Суточная сводка: имена и числа, без строк лога. - Отдельный инжект и отдельная мысль: в проходе это молчит, но раз в сутки - мастер видит, что именно идёт до сих пор и в какую сторону. + Уходит раз в сутки всегда, даже когда длящегося нет и всё чисто: строка + про проходы и охват - единственное, чем здоровая тишина отличается от + отвалившегося крона, побитого состояния и не поднявшегося стека. """ + sweep = report.sweep rows = grouped(report.ongoing) lines = [ - f"{SELF_MARK}: длящееся, сводка за {report.day}.", + f"{SELF_MARK}: сводка за {report.day}.", ( - f"Идёт до сих пор: {len(rows)} рядов " - f"({len(report.ongoing)} разных строк), за закрытые сутки:" + f"Проходов за сутки {report.passes} из {PASSES_A_DAY} ожидавшихся; " + f"в последнем прочитано {len(sweep.read)} стеков из {sweep.in_scope} " + f"в области ({', '.join(sweep.scope)})." ), ] + if report.misses or report.blind: + lines.append( + f"Отказов доступа за те сутки: чтений стеков {report.misses}, " + f"проходов без ответа Komodo {report.blind}." + ) + if not rows: + lines.append("Длящегося нет: всё, о чём я говорил, стихло или не повторялось.") + return "\n".join(lines) + lines.append( + f"Идёт до сих пор: {len(rows)} рядов " + f"({len(report.ongoing)} разных строк), за те сутки:" + ) lines.extend(_daily_line(row, tz) for row in rows[:MAX_DAILY]) if len(rows) > MAX_DAILY: lines.append(f"…и ещё {len(rows) - MAX_DAILY} рядов.") diff --git a/tests/test_komodo_logs.py b/tests/test_komodo_logs.py index 1490013..44d7573 100644 --- a/tests/test_komodo_logs.py +++ b/tests/test_komodo_logs.py @@ -4,6 +4,9 @@ from beaver_agent.hands.komodo import Komodo from beaver_agent.hands.komodo_logs import ( KEEP, SELF_MARK, + SURGE_CEILING, + SURGE_FACTOR, + SURGE_MIN, Seen, StackScan, Sweep, @@ -531,7 +534,7 @@ def test_a_continuing_trouble_comes_back_in_the_daily_summary(tmp_path): assert night.summary and len(night.ongoing) == 1 assert night.new == () and not night.worth_telling text = daily(night, UTC) - assert "длящееся, сводка за 2026-09-21" in text + assert "сводка за 2026-09-20" in text # числа - про закрывшиеся сутки assert "gitea/svc ошибка, с 20.09 09:00, за сутки 5, первые сутки" in text assert "ERROR" not in text # образцов строк в сводке нет намеренно told(state, night) @@ -657,3 +660,71 @@ def test_the_summary_folds_the_variants_of_one_service_into_one_row(tmp_path): text = daily(night, UTC) assert "Идёт до сих пор: 1 рядов (3 разных строк)" in text assert "gitea/svc ошибка, строк 3 видов, с 20.09 09:00, за сутки 12" in text + + +def test_the_daily_summary_arrives_even_when_all_is_quiet(tmp_path): + # Мёртвый джоб и чистый флот должны выглядеть по-разному. + state = seen(tmp_path) + for hour in (10, 13, 16, 19, 22): + digest(state, swept([read_stack("gitea", log())], at=at(20, hour))) + night = digest(state, swept([read_stack("gitea", log())], at=at(21, 1, 40))) + assert night.summary and night.ongoing == () + assert not night.worth_telling # обычного инжекта нет, суточный - есть + text = daily(night, UTC) + assert text.splitlines() == [ + "Логи флота: сводка за 2026-09-20.", + "Проходов за сутки 5 из 8 ожидавшихся; в последнем прочитано 1 стеков " + "из 1 в области (dell-home, personal-main).", + "Длящегося нет: всё, о чём я говорил, стихло или не повторялось.", + ] + + +def test_the_daily_summary_counts_the_refusals(tmp_path): + state = seen(tmp_path) + digest(state, swept([StackScan(stack="gitea", error="timeout")], at=at(20, 10))) + digest(state, Sweep(at=at(20, 13), unreachable="OSError: нет связи")) + night = digest(state, swept([read_stack("gitea", log())], at=at(21, 1, 40))) + assert ( + "Отказов доступа за те сутки: чтений стеков 1, проходов без ответа Komodo 1" + in daily(night, UTC) + ) + + +def test_a_slowly_growing_trouble_still_breaks_through(tmp_path): + # Варёная лягушка: норма замерла на молодости беды и за ростом не тянется. + state = seen(tmp_path) + told(state, digest(state, swept([burst("gitea", stamps(20, 8, 1))], at=at(20, 9)))) + counts = [1, 1, 2, 3, 4, 6, 9, 13] + hour = 10 + seen_times = stamps(20, 8, 1) + surged = [] + for n in counts: + seen_times = seen_times + stamps(20, hour - 1, n, start=10) + report = digest(state, swept([burst("gitea", seen_times)], at=at(20, hour))) + if report.surge: + surged.append((hour, report.surge[0].gain, report.surge[0].norm)) + told(state, report) + hour += 1 + (entry,) = state.entries.values() + assert entry.norm == 1.0 # заморожена по первым трём активным проходам + assert surged and surged[0][1] >= SURGE_MIN + assert surged[0][2] == 1.0 + + +def test_the_ceiling_fires_without_any_relative_norm(tmp_path): + # Беда, чья собственная норма уже огромна: относительный порог её не возьмёт. + state = seen(tmp_path) + times = stamps(20, 8, 40) + told(state, digest(state, swept([burst("gitea", times)], at=at(20, 9)))) + for hour in (12, 15): + times = times + stamps(20, hour - 1, 40, start=10) + digest(state, swept([burst("gitea", times)], at=at(20, hour))) + (entry,) = state.entries.values() + assert entry.norm == 40.0 + huge = stamps(20, 17, 55, start=0) + spike = digest(state, swept([burst("gitea", times + huge)], at=at(20, 18))) + (item,) = spike.surge + assert item.gain == 55 # 55 < 4 × 40, взял потолок, а не кратность + assert item.gain < SURGE_FACTOR * item.norm + assert item.gain >= SURGE_CEILING + assert "Всплеск знакомого (1)" in brief(spike)