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

This commit is contained in:
hh committed 2026-09-21 00:09:04 +00:00
1 parent a0fe09811d
commit f3e4d51e4e
2 files changed
+202 -36

No files matched your search

+130 -35
View File
@@ -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} рядов.")
+72 -1
View File
@@ -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)