fix(hands,jobs): суточная сводка уходит и в чистые сутки, норма всплеска замирает на молодости беды

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:
+    if gain >= SURGE_CEILING:
-        return False
+        return True
-    return entry.surged is None or at - entry.surged > SURGE_HOLD
+    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,
+        summary=seen.closed is not None and seen.summary_day != day,
-        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"Проходов за сутки {report.passes} из {PASSES_A_DAY} ожидавшихся; "
-            f"({len(report.ongoing)} разных строк), за закрытые сутки:"
+            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} рядов.")

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)