feat(hands,jobs): длящаяся беда не пропадает - суточная сводка и всплеск против своей нормы

This commit is contained in:
hh committed 2026-09-21 00:09:04 +00:00
1 parent b6c5050d69
commit a0fe09811d
4 files changed
+494 -26

No files matched your search

+278 -12
View File
@@ -6,6 +6,12 @@
и обратный переход «было → нет» - с временем последнего события, не с временем и обратный переход «было → нет» - с временем последнего события, не с временем
прохода (логи берутся с `--timestamps`, время в строке настоящее). прохода (логи берутся с `--timestamps`, время в строке настоящее).
Молчать - не то же самое, что забыть. Беда, идущая неделю, после первого
доклада не исчезает: она переходит в длящиеся и раз в сутки идёт отдельной
короткой сводкой (имена и числа, без строк), а если за проход её стало в разы
больше собственной нормы - снова дёргает сразу. Затихание наоборот: не тревога,
а строка «стихло» с временем последнего события.
Показанную строку лога чистит общий `security.redact` - тот же, что стоит на Показанную строку лога чистит общий `security.redact` - тот же, что стоит на
логах и на выдаче MCP: правила в одном месте, и он знает литеральные значения логах и на выдаче MCP: правила в одном месте, и он знает литеральные значения
секретов из env. Голые блобы без имени рядом он не трогает намеренно - id секретов из env. Голые блобы без имени рядом он не трогает намеренно - id
@@ -37,12 +43,16 @@ __all__ = [
"SIGNALS", "SIGNALS",
"TAIL", "TAIL",
"Entry", "Entry",
"Ongoing",
"Report", "Report",
"Seen", "Seen",
"StackScan", "StackScan",
"Surge",
"Sweep", "Sweep",
"brief", "brief",
"daily",
"digest", "digest",
"grouped",
"read_stack", "read_stack",
] ]
@@ -94,10 +104,33 @@ MAX_TROUBLE = 10
GAP_NAMES = 3 GAP_NAMES = 3
UNPARSED_LOUD = 10 UNPARSED_LOUD = 10
"""Столько неразобранных строк на проход - уже не обрезанная голова, а дыра.""" """Столько неразобранных строк на проход - уже не обрезанная голова, а дыра."""
MAX_DAILY = 20
KEEP = timedelta(days=14) KEEP = timedelta(days=14)
"""Сколько помнить беду, которой больше не видно: дальше пусть будет новой.""" """Сколько помнить беду, которой больше не видно: дальше пусть будет новой."""
QUIET_AFTER = timedelta(hours=24)
"""Сутки без единого нового события - беда считается стихшей, даже если её
строка ещё лежит в хвосте. Иначе на тихом стеке «стихло» ждало бы неделями,
пока строку не вытеснит."""
SURGE_FACTOR = 4.0
"""Во сколько раз проход должен перебить собственную норму беды, чтобы снова
стоить тревоги. Проходов восемь в сутки, и счёт за проход сам по себе гуляет
вдвое (деплой, ночной крон, перезапуск) - вчетверо это уже не дрожание.
Считается по среднему за прошлые активные проходы, то есть у каждой беды
норма своя; хвост ограничен, поэтому взрыв упирается в TAIL и видно скорее
«стало на порядок», чем точную кратность."""
SURGE_MIN = 10
"""Пол в штуках: без него «было одно, стало четыре» будило бы каждый раз."""
SURGE_PASSES = 3
"""Пока беду видели меньше трёх раз, нормы у неё нет и сравнивать не с чем."""
SURGE_HOLD = timedelta(hours=12)
"""Одна беда - не чаще раза в полсуток, даже если растёт ступенями."""
TREND_UP, TREND_DOWN = 1.5, 0.67
"""Полтора раза в сутках - уже тренд, между ними - то же самое."""
KEY_CHARS = 12 KEY_CHARS = 12
STATE_VERSION = 1 STATE_VERSION = 2
EPOCH = datetime(1970, 1, 1, tzinfo=UTC) EPOCH = datetime(1970, 1, 1, tzinfo=UTC)
@@ -112,6 +145,15 @@ class Hit:
sample: str sample: str
at: datetime | None at: datetime | None
count: int count: int
times: tuple[datetime, ...] = ()
"""Время каждого повтора в хвосте: хвост перечитывается каждый проход, и
без этого одни и те же строки считались бы заново по восемь раз в сутки."""
def since(self, after: datetime | None) -> int:
"""Сколько повторов случилось позже ``after`` - то есть новых для нас."""
if after is None:
return self.count
return sum(1 for t in self.times if t > after)
@dataclass(frozen=True, slots=True) @dataclass(frozen=True, slots=True)
@@ -199,13 +241,68 @@ class Entry:
looked: datetime | None = None looked: datetime | None = None
"""Когда её последний раз видели в хвосте: по этому и забываем.""" """Когда её последний раз видели в хвосте: по этому и забываем."""
count: int = 0 count: int = 0
"""Всего повторов, посчитанных приростом, а не перечитыванием хвоста."""
passes: int = 0
"""В скольких проходах она прирастала: по ним и считается её норма."""
day_count: int = 0
day_before: int = 0
day_earlier: int = 0
"""Повторы за текущие сутки и за двое прошлых - из них сводка и тренд."""
told: bool = False told: bool = False
"""Сказали ли о ней мастеру. Инжект не доехал - не сказали, повторим.""" """Сказали ли о ней мастеру. Инжект не доехал - не сказали, повторим."""
announced: bool = False
"""Про неё говорили именно как про новую, а не приняли в базовую линию:
«стихло» бывает только про то, о чём мастер слышал."""
quieted: datetime | None = None
"""Когда доложили, что стихла. Появится новое событие - снова новость."""
surged: datetime | None = None
"""Когда последний раз докладывали о всплеске: чаще раза в полсуток - нет."""
@property @property
def where(self) -> str: def where(self) -> str:
return f"{self.stack}/{self.service}" 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:
"""Длящееся одним рядом: стек, сервис и сигнал, а не отдельная строка.
Один сервис сыплет десяток похожих строк (у caddy их семь видов), и в
сводке каждая своей строкой - та же стена, от которой сводку и делали.
"""
where: str
signal: str
first: datetime | None
day_before: int
day_earlier: int
kinds: int
"""Сколько разных строк слилось в этот ряд."""
def trend(self) -> str:
if not self.day_earlier:
return "первые сутки"
ratio = self.day_before / self.day_earlier
if ratio >= TREND_UP:
return f"растёт (было {self.day_earlier})"
if ratio <= TREND_DOWN:
return f"падает (было {self.day_earlier})"
return f"ровно (было {self.day_earlier})"
@dataclass(frozen=True, slots=True)
class Surge:
"""Знакомая беда, которой за проход стало в разы больше своей нормы."""
entry: Entry
gain: int
norm: float
@dataclass(frozen=True, slots=True) @dataclass(frozen=True, slots=True)
class Report: class Report:
@@ -213,7 +310,14 @@ class Report:
sweep: Sweep sweep: Sweep
new: tuple[Entry, ...] = () new: tuple[Entry, ...] = ()
surge: tuple[Surge, ...] = ()
quiet: tuple[Entry, ...] = () quiet: tuple[Entry, ...] = ()
ongoing: tuple[Entry, ...] = ()
"""Длящееся: молчит в обычном проходе, идёт в суточную сводку."""
summary: bool = False
"""Сутки закрылись и сводку по длящемуся ещё не отдавали."""
day: str = ""
"""Сутки, за которые считается сводка (те, что только что закрылись)."""
trouble: tuple[str, ...] = () trouble: tuple[str, ...] = ()
gaps: tuple[str, ...] = () gaps: tuple[str, ...] = ()
cold: bool = False cold: bool = False
@@ -225,7 +329,8 @@ class Report:
@property @property
def worth_telling(self) -> bool: def worth_telling(self) -> bool:
return bool(self.new or self.quiet or self.trouble or self.cold) """Суточная сводка сюда не входит: она едет своим инжектом."""
return bool(self.new or self.surge or self.quiet or self.trouble or self.cold)
@dataclass(slots=True) @dataclass(slots=True)
@@ -239,6 +344,10 @@ class Seen:
trouble: tuple[str, ...] = () trouble: tuple[str, ...] = ()
"""О каких отказах уже сказали: Komodo лежит - скажем один раз, не каждые 3 ч.""" """О каких отказах уже сказали: Komodo лежит - скажем один раз, не каждые 3 ч."""
last_pass: datetime | None = None last_pass: datetime | None = None
day: str | None = None
"""Локальные сутки, которым принадлежат суточные счётчики записей."""
summary_day: str | None = None
"""Сутки, за которые сводка по длящемуся уже доехала до мастера."""
fresh: bool = True fresh: bool = True
"""Файла не было: базовую линию только снимаем, стену старых бед не шлём.""" """Файла не было: базовую линию только снимаем, стену старых бед не шлём."""
@@ -261,7 +370,14 @@ class Seen:
last=_parse(row.get("last")), last=_parse(row.get("last")),
looked=_parse(row.get("looked")), looked=_parse(row.get("looked")),
count=int(row.get("count", 0)), count=int(row.get("count", 0)),
passes=int(row.get("passes", 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)),
told=bool(row.get("told")), told=bool(row.get("told")),
announced=bool(row.get("announced")),
quieted=_parse(row.get("quieted")),
surged=_parse(row.get("surged")),
) )
for key, row in raw.get("entries", {}).items() for key, row in raw.get("entries", {}).items()
} }
@@ -271,6 +387,8 @@ class Seen:
baselined=set(raw.get("baselined", ())), baselined=set(raw.get("baselined", ())),
trouble=tuple(raw.get("trouble", ())), trouble=tuple(raw.get("trouble", ())),
last_pass=_parse(raw.get("last_pass")), last_pass=_parse(raw.get("last_pass")),
day=raw.get("day"),
summary_day=raw.get("summary_day"),
fresh=False, fresh=False,
) )
@@ -278,6 +396,8 @@ class Seen:
body = { body = {
"version": STATE_VERSION, "version": STATE_VERSION,
"last_pass": _iso(self.last_pass), "last_pass": _iso(self.last_pass),
"day": self.day,
"summary_day": self.summary_day,
"baselined": sorted(self.baselined), "baselined": sorted(self.baselined),
"trouble": list(self.trouble), "trouble": list(self.trouble),
"entries": { "entries": {
@@ -290,7 +410,14 @@ class Seen:
"last": _iso(e.last), "last": _iso(e.last),
"looked": _iso(e.looked), "looked": _iso(e.looked),
"count": e.count, "count": e.count,
"passes": e.passes,
"day_count": e.day_count,
"day_before": e.day_before,
"day_earlier": e.day_earlier,
"told": e.told, "told": e.told,
"announced": e.announced,
"quieted": _iso(e.quieted),
"surged": _iso(e.surged),
} }
for key, e in self.entries.items() for key, e in self.entries.items()
}, },
@@ -301,13 +428,24 @@ class Seen:
tmp.replace(self.path) tmp.replace(self.path)
def mark_told(self, report: Report) -> None: def mark_told(self, report: Report) -> None:
"""Инжект доехал: новое больше не новое, стихшее забывается.""" """Инжект доехал: новое сказано, стихшее помечено, всплеск выдержан.
Стихшее не выбрасывается, а помечается: его строка может ещё лежать в
хвосте, и выброшенная запись завтра же вернулась бы как «новая».
"""
for entry in report.new: for entry in report.new:
entry.told = True entry.told = True
entry.announced = True
for item in report.surge:
item.entry.surged = report.sweep.at
for entry in report.quiet: for entry in report.quiet:
self.entries.pop(entry.key, None) entry.quieted = report.sweep.at
self.trouble = report.trouble self.trouble = report.trouble
def mark_daily(self, report: Report) -> None:
"""Сводка доехала: за эти сутки больше не повторяем."""
self.summary_day = report.day
def _iso(at: datetime | None) -> str | None: def _iso(at: datetime | None) -> str | None:
return at.isoformat() if at else None return at.isoformat() if at else None
@@ -381,6 +519,7 @@ def read_stack(stack: str, log: dict[str, Any]) -> StackScan:
sample=(before.sample if before else redact(rest)[:SAMPLE_CHARS]), sample=(before.sample if before else redact(rest)[:SAMPLE_CHARS]),
at=at or (before.at if before else None), at=at or (before.at if before else None),
count=(before.count if before else 0) + 1, count=(before.count if before else 0) + 1,
times=((*before.times, at) if before else (at,)),
) )
return StackScan( return StackScan(
stack=stack, stack=stack,
@@ -404,14 +543,41 @@ def _forget(seen: Seen, now: datetime) -> None:
del seen.entries[key] del seen.entries[key]
def digest(seen: Seen, sweep: Sweep) -> Report: def _roll(seen: Seen, day: str) -> None:
"""Сравнить проход с прошлым: что новое, что стихло, о чём молчать.""" """Сутки сменились: закрытый день уезжает в `day_before`, счёт с нуля."""
if seen.day == day:
return
if seen.day is not None:
for entry in seen.entries.values():
entry.day_earlier = entry.day_before
entry.day_before = entry.day_count
entry.day_count = 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:
return False
if gain < SURGE_FACTOR * entry.norm:
return False
return entry.surged is None or at - entry.surged > SURGE_HOLD
def digest(seen: Seen, sweep: Sweep, tz: tzinfo = UTC) -> Report:
"""Сравнить проход с прошлым: что новое, что всплеск, что стихло, что длится."""
gaps = sweep.gaps(seen.last_pass) gaps = sweep.gaps(seen.last_pass)
_forget(seen, sweep.at) _forget(seen, sweep.at)
day = sweep.at.astimezone(tz).date().isoformat()
_roll(seen, day)
looked = {scan.stack for scan in sweep.read} looked = {scan.stack for scan in sweep.read}
newcomers = looked - seen.baselined newcomers = looked - seen.baselined
hits = {hit.key: hit for scan in sweep.read for hit in scan.hits} hits = {hit.key: hit for scan in sweep.read for hit in scan.hits}
baseline = 0 baseline = 0
born: set[str] = set()
surge: list[Surge] = []
for key, hit in hits.items(): for key, hit in hits.items():
entry = seen.entries.get(key) entry = seen.entries.get(key)
if entry is None: if entry is None:
@@ -421,24 +587,54 @@ def digest(seen: Seen, sweep: Sweep) -> Report:
service=hit.service, service=hit.service,
signal=hit.signal, signal=hit.signal,
sample=hit.sample, sample=hit.sample,
first=hit.at or sweep.at, first=hit.times[0] if hit.times else sweep.at,
looked=sweep.at, looked=sweep.at,
) )
seen.entries[key] = entry seen.entries[key] = entry
born.add(key)
if hit.stack in newcomers: if hit.stack in newcomers:
# Стек читаем впервые: в хвосте лежит всё его прошлое, и вываливать # Стек читаем впервые: в хвосте лежит всё его прошлое, и вываливать
# его как «новое» - врать. Принимаем за данность, дальше - только рост. # его как «новое» - врать. Принимаем за данность, дальше - только рост.
entry.told = True entry.told = True
baseline += 1 baseline += 1
entry.last = hit.at or entry.last or sweep.at
entry.looked = sweep.at entry.looked = sweep.at
entry.count += hit.count gain = hit.since(entry.last)
if not gain:
# Та же строка, что и в прошлый проход: хвост перечитан, беда не росла.
continue
if _surging(entry, gain, sweep.at):
surge.append(Surge(entry=entry, gain=gain, norm=entry.norm))
if entry.quieted is not None:
# Стихшая беда вернулась: это снова новость, а не продолжение.
entry.quieted = None
entry.told = False
entry.count += gain
entry.passes += 1
entry.day_count += gain
entry.last = hit.at or entry.last or sweep.at
seen.baselined |= looked seen.baselined |= looked
# Стихло - только у стеков, которые прочитались: чего не видели, того не судим. # Стихло - только про то, о чём говорили, и только у прочитанных стеков:
# чего не видели, того не судим, а про фон мастер и не слышал.
quiet = tuple( quiet = tuple(
e e
for e in seen.entries.values() for e in seen.entries.values()
if e.told and e.stack in looked and e.key not in hits if e.announced
and e.quieted is None
and e.stack in looked
and e.key not in born
and (
e.key not in hits
or (e.last is not None and sweep.at - e.last > QUIET_AFTER)
)
)
# Длящееся: молчит в проходе, но живёт в состоянии и едет в суточную сводку.
ongoing = tuple(
e
for e in seen.entries.values()
if e.quieted is None
and e.day_before > 0
and e.last is not None
and sweep.at - e.last <= QUIET_AFTER
) )
seen.last_pass = sweep.at seen.last_pass = sweep.at
# Холодный старт без единого прочитанного стека базой не считается: иначе # Холодный старт без единого прочитанного стека базой не считается: иначе
@@ -450,7 +646,11 @@ def digest(seen: Seen, sweep: Sweep) -> Report:
return Report( return Report(
sweep=sweep, sweep=sweep,
new=tuple(sorted(fresh, key=lambda e: (e.stack, e.service))), new=tuple(sorted(fresh, key=lambda e: (e.stack, e.service))),
surge=tuple(sorted(surge, key=lambda s: -s.gain)),
quiet=tuple(sorted(quiet, key=lambda e: (e.stack, e.service))), 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,
trouble=trouble, trouble=trouble,
gaps=gaps, gaps=gaps,
cold=cold, cold=cold,
@@ -505,6 +705,66 @@ def _entry_line(entry: Entry, tz: tzinfo, *, new: bool) -> str:
return head + entry.sample return head + entry.sample
def _surge_line(item: Surge, tz: tzinfo) -> str:
entry = item.entry
return (
f"- {entry.where} {_when(entry.last, tz)} {entry.signal}: "
f"×{item.gain} за проход при норме ×{item.norm:.1f}, "
f"идёт с {_when(entry.first, tz)} - {entry.sample}"
)
def grouped(entries: tuple[Entry, ...]) -> tuple[Ongoing, ...]:
"""Слить длящееся по стеку, сервису и сигналу - рядов, а не строк."""
rows: dict[tuple[str, str], list[Entry]] = {}
for entry in entries:
rows.setdefault((entry.where, entry.signal), []).append(entry)
out = [
Ongoing(
where=where,
signal=signal,
first=min((e.first for e in group if e.first), default=None),
day_before=sum(e.day_before for e in group),
day_earlier=sum(e.day_earlier for e in group),
kinds=len(group),
)
for (where, signal), group in rows.items()
]
return tuple(sorted(out, key=lambda o: -o.day_before))
def _daily_line(row: Ongoing, tz: tzinfo) -> str:
kinds = f", строк {row.kinds} видов" if row.kinds > 1 else ""
return (
f"- {row.where} {row.signal}{kinds}, с {_when(row.first, tz)}, "
f"за сутки {row.day_before}, {row.trend()}"
)
def daily(report: Report, tz: tzinfo = UTC) -> str:
"""Суточная сводка по длящемуся: имена и числа, без строк лога.
Отдельный инжект и отдельная мысль: в проходе это молчит, но раз в сутки
мастер видит, что именно идёт до сих пор и в какую сторону.
"""
rows = grouped(report.ongoing)
lines = [
f"{SELF_MARK}: длящееся, сводка за {report.day}.",
(
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} рядов.")
lines.append(
"Новым это не считается и в проходах молчит; строки смотри "
"komodo(logs) или komodo(search_logs)."
)
return "\n".join(lines)
def brief(report: Report, tz: tzinfo = UTC) -> str: def brief(report: Report, tz: tzinfo = UTC) -> str:
"""Инжект: что нового, где, сколько раз - и всегда область просмотра.""" """Инжект: что нового, где, сколько раз - и всегда область просмотра."""
sweep = report.sweep sweep = report.sweep
@@ -531,8 +791,14 @@ def brief(report: Report, tz: tzinfo = UTC) -> str:
lines.extend(_entry_line(e, tz, new=True) for e in report.new[:MAX_NEW]) lines.extend(_entry_line(e, tz, new=True) for e in report.new[:MAX_NEW])
if len(report.new) > MAX_NEW: if len(report.new) > MAX_NEW:
lines.append(f"…и ещё {len(report.new) - MAX_NEW} - смотри komodo(logs).") lines.append(f"…и ещё {len(report.new) - MAX_NEW} - смотри komodo(logs).")
elif not report.cold and sweep.read: elif not report.cold and sweep.read and not report.surge:
lines.append("Нового в этой области нет.") lines.append("Нового в этой области нет.")
if report.surge:
lines.append(
f"Всплеск знакомого ({len(report.surge)}) - строка не новая, "
"но её стало в разы больше своей нормы:"
)
lines.extend(_surge_line(item, tz) for item in report.surge[:MAX_NEW])
if report.quiet: if report.quiet:
lines.append(f"Стихло ({len(report.quiet)}), время - события, не прохода:") lines.append(f"Стихло ({len(report.quiet)}), время - события, не прохода:")
lines.extend(_entry_line(e, tz, new=False) for e in report.quiet[:MAX_QUIET]) lines.extend(_entry_line(e, tz, new=False) for e in report.quiet[:MAX_QUIET])
+2
View File
@@ -32,6 +32,8 @@ jobs = [
Job("куратор", curate, cron="0 2,8,12,16,20 * * *", critical=False), Job("куратор", curate, cron="0 2,8,12,16,20 * * *", critical=False),
# Логи - раз в 3 часа и на ":40": на ":00" ротация и куратор. Чаще смысла # Логи - раз в 3 часа и на ":40": на ":00" ротация и куратор. Чаще смысла
# мало (36 стеков = 36 чтений за проход), реже - хвост уезжает совсем. # мало (36 стеков = 36 чтений за проход), реже - хвост уезжает совсем.
# Проход 01:40 - первый после полуночи: он же несёт суточную сводку по
# длящемуся, чтобы фон не исчезал из виду, доложенный однажды.
Job("логи", logs_watch, cron="40 1,4,7,10,13,16,19,22 * * *", critical=False), Job("логи", logs_watch, cron="40 1,4,7,10,13,16,19,22 * * *", critical=False),
Job("deploy", deploy, webhook=True), Job("deploy", deploy, webhook=True),
Job("komodo", komodo_alert, webhook=True, dedupe=False), Job("komodo", komodo_alert, webhook=True, dedupe=False),
+24 -14
View File
@@ -25,6 +25,7 @@ from beaver_agent.hands.komodo_logs import (
StackScan, StackScan,
Sweep, Sweep,
brief, brief,
daily,
digest, digest,
read_stack, read_stack,
) )
@@ -99,26 +100,35 @@ async def sweep(
async def logs_watch(run: JobRun) -> None: async def logs_watch(run: JobRun) -> None:
"""Проход по логам: состояние на диске, инжект - только на новом.""" """Проход по логам: состояние на диске, инжект - на новом и раз в сутки.
Инжекта два и они разные: обычный - про новое, всплески и отбой; суточный -
про длящееся, которое в проходах молчит. Первый проход суток у нас в 01:40,
он же и несёт сводку: в 00:00 ротация мастера, лезть туда незачем.
"""
if KOMODO is None: if KOMODO is None:
_log.info("логи: руки komodo нет, проход пропущен") _log.info("логи: руки komodo нет, проход пропущен")
return return
seen = Seen.load(STATE_FILE) seen = Seen.load(STATE_FILE)
report = digest(seen, await sweep(KOMODO)) report = digest(seen, await sweep(KOMODO), ZONE)
if not report.worth_telling: if report.worth_telling and await run.inject_master(
brief(report, ZONE), urgency="normal", origin="логи"
):
seen.mark_told(report)
if report.summary and await run.inject_master(
daily(report, ZONE), urgency="normal", origin="логи"
):
seen.mark_daily(report)
seen.save() seen.save()
_log.info( _log.info(
"логи: нового нет, стеков прочитано %s из %s", "логи: новое %s, всплеск %s, стихло %s, длится %s (сводка %s), "
"не прочитано %s, стеков %s из %s",
len(report.new),
len(report.surge),
len(report.quiet),
len(report.ongoing),
report.summary,
len(report.trouble),
len(report.sweep.read), len(report.sweep.read),
report.sweep.in_scope, report.sweep.in_scope,
) )
return
if await run.inject_master(brief(report, ZONE), urgency="normal", origin="логи"):
seen.mark_told(report)
seen.save()
_log.info(
"логи: новое %s, стихло %s, не прочитано %s",
len(report.new),
len(report.quiet),
len(report.trouble),
)
+190
View File
@@ -8,7 +8,9 @@ from beaver_agent.hands.komodo_logs import (
StackScan, StackScan,
Sweep, Sweep,
brief, brief,
daily,
digest, digest,
grouped,
read_stack, read_stack,
) )
from beaver_agent.jobs.logs import sweep as sweep_fleet from beaver_agent.jobs.logs import sweep as sweep_fleet
@@ -467,3 +469,191 @@ def test_a_bare_blob_stays_readable():
) )
(hit,) = scan.hits (hit,) = scan.hits
assert "kJ8sdfLKJ23kjhsdf98234x" in hit.sample assert "kJ8sdfLKJ23kjhsdf98234x" in hit.sample
def stamps(day, hour, count, start=0):
return [
f"2026-09-{day:02d}T{hour:02d}:{m:02d}:00.0"
for m in range(start, start + count)
]
def burst(stack, times, text="ERROR всё та же беда", service="svc"):
"""Хвост стека, где одна и та же беда повторилась в перечисленные минуты."""
return read_stack(stack, log(*(line(service, t, text) for t in times)))
def at(day, hour, minute=0):
return datetime(2026, 9, day, hour, minute, tzinfo=UTC)
def told(state, report):
state.mark_told(report)
return report
def test_a_continuing_trouble_is_told_once_and_then_keeps_quiet(tmp_path):
state = seen(tmp_path)
first = told(
state, digest(state, swept([burst("gitea", stamps(20, 9, 3))], at=at(20, 10)))
)
assert len(first.new) == 1
# Хвост перечитан: те же строки плюс свежие - беда идёт, но новостью не стала.
later = digest(
state,
swept([burst("gitea", stamps(20, 9, 3) + stamps(20, 12, 4))], at=at(20, 13)),
)
assert later.new == () and later.surge == () and later.quiet == ()
assert not later.worth_telling
assert later.ongoing == () # за прошлые сутки её ещё не было
def test_the_reread_tail_does_not_inflate_the_count(tmp_path):
state = seen(tmp_path)
told(state, digest(state, swept([burst("gitea", stamps(20, 9, 3))], at=at(20, 10))))
for hour in (13, 16, 19):
digest(state, swept([burst("gitea", stamps(20, 9, 3))], at=at(20, hour)))
(entry,) = state.entries.values()
assert entry.count == 3 # три повтора, а не три на каждый из четырёх проходов
assert entry.passes == 1
def test_a_continuing_trouble_comes_back_in_the_daily_summary(tmp_path):
state = seen(tmp_path)
told(state, digest(state, swept([burst("gitea", stamps(20, 9, 5))], at=at(20, 10))))
# Первый проход следующих суток - 01:40, он же несёт сводку.
night = digest(
state,
swept([burst("gitea", stamps(20, 9, 5) + stamps(21, 1, 2))], at=at(21, 1, 40)),
)
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 "gitea/svc ошибка, с 20.09 09:00, за сутки 5, первые сутки" in text
assert "ERROR" not in text # образцов строк в сводке нет намеренно
told(state, night)
state.mark_daily(night)
# Тот же день, следующий проход: сводку уже отдали.
again = digest(
state,
swept([burst("gitea", stamps(20, 9, 5) + stamps(21, 1, 2))], at=at(21, 4, 40)),
)
assert again.ongoing and not again.summary
def test_the_summary_says_which_way_it_is_going(tmp_path):
state = seen(tmp_path)
told(state, digest(state, swept([burst("gitea", stamps(20, 9, 2))], at=at(20, 10))))
day_two = swept(
[burst("gitea", stamps(20, 9, 2) + stamps(21, 9, 8))], at=at(21, 10)
)
told(state, digest(state, day_two))
third = digest(
state,
swept(
[burst("gitea", stamps(20, 9, 2) + stamps(21, 9, 8) + stamps(22, 1, 1))],
at=at(22, 1, 40),
),
)
assert "за сутки 8, растёт (было 2)" in daily(third, UTC)
def test_a_surge_of_the_familiar_breaks_the_silence(tmp_path):
state = seen(tmp_path)
state_report = digest(
state, swept([burst("gitea", stamps(20, 9, 1))], at=at(20, 10))
)
told(state, state_report)
for hour, minute in ((13, 12), (16, 15)):
digest(
state,
swept([burst("gitea", stamps(20, hour - 1, 1, minute))], at=at(20, hour)),
)
(entry,) = state.entries.values()
assert entry.passes == 3 and entry.norm == 1.0
spike = digest(state, swept([burst("gitea", stamps(20, 18, 12))], at=at(20, 19)))
(item,) = spike.surge
assert item.gain == 12 and item.norm == 1.0
assert spike.new == () and spike.worth_telling
text = brief(spike)
assert "Всплеск знакомого (1)" in text
assert "×12 за проход при норме ×1.0" in text
assert "Нового в этой области нет" not in text
# Второй такой же проход внутри выдержки молчит: это уже не новость.
told(state, spike)
more = digest(state, swept([burst("gitea", stamps(20, 21, 12))], at=at(20, 22)))
assert more.surge == () and not more.worth_telling
def test_a_small_jump_is_not_a_surge(tmp_path):
state = seen(tmp_path)
told(state, digest(state, swept([burst("gitea", stamps(20, 9, 1))], at=at(20, 10))))
for hour in (13, 16):
digest(
state,
swept([burst("gitea", stamps(20, hour - 1, 1, hour))], at=at(20, hour)),
)
# Вчетверо больше, но всего четыре штуки: пол в SURGE_MIN держит тишину.
small = digest(state, swept([burst("gitea", stamps(20, 18, 4))], at=at(20, 19)))
assert small.surge == () and not small.worth_telling
def test_a_trouble_gone_silent_is_reported_even_while_its_line_lingers(tmp_path):
state = seen(tmp_path)
tail = burst("gitea", stamps(20, 9, 2))
told(state, digest(state, swept([tail], at=at(20, 10))))
# Сутки та же строка лежит в хвосте, новых событий нет.
assert not digest(state, swept([tail], at=at(20, 22))).quiet
stopped = digest(state, swept([tail], at=at(21, 12)))
(gone,) = stopped.quiet
assert gone.last == at(20, 9, 1)
assert "последнее в 20.09 09:01" in brief(stopped)
told(state, stopped)
assert digest(state, swept([tail], at=at(21, 16))).quiet == ()
def test_a_trouble_that_returns_after_the_all_clear_is_new_again(tmp_path):
state = seen(tmp_path)
tail = burst("gitea", stamps(20, 9, 2))
told(state, digest(state, swept([tail], at=at(20, 10))))
told(state, digest(state, swept([tail], at=at(21, 12)))) # стихла
back = digest(
state,
swept([burst("gitea", stamps(20, 9, 2) + stamps(21, 18, 3))], at=at(21, 19)),
)
assert len(back.new) == 1 and back.worth_telling
def test_the_background_of_the_baseline_never_claims_to_have_stopped(tmp_path):
# Про фон, принятый в базовую линию, мастер не слышал - «стихло» про него врёт.
state = seen(tmp_path, known=())
state.fresh = False
cold = digest(state, swept([burst("lodge", stamps(20, 9, 2))], at=at(20, 10)))
assert cold.new == () and cold.baseline == 1
gone = digest(state, swept([read_stack("lodge", log())], at=at(20, 13)))
assert gone.quiet == () and not gone.worth_telling
def test_the_summary_folds_the_variants_of_one_service_into_one_row(tmp_path):
state = seen(tmp_path)
# Разные по смыслу строки: отличие в одних цифрах - это одна и та же беда.
variants = [
burst("gitea", stamps(20, 9, 4), text=f"ERROR {what}")
for what in ("push отклонён", "миграция не прошла", "ssh-ключ отвергнут")
]
told(state, digest(state, swept(variants, at=at(20, 10))))
night = digest(state, swept(variants, at=at(21, 1, 40)))
(row,) = grouped(night.ongoing)
assert row.kinds == 3 and row.day_before == 12
text = daily(night, UTC)
assert "Идёт до сих пор: 1 рядов (3 разных строк)" in text
assert "gitea/svc ошибка, строк 3 видов, с 20.09 09:00, за сутки 12" in text