"""Логи флота периодами: что в хвостах похоже на беду и чего там раньше не было. Ходит и читает джоб `jobs/logs.py`, судит этот модуль. Правило одно: мастера дёргает только НОВОЕ. То, что молотит в логе третьи сутки, уже сказано один раз и больше не показывается; показывается то, чего в прошлом проходе не было, и обратный переход «было → нет» - с временем последнего события, не с временем прохода (логи берутся с `--timestamps`, время в строке настоящее). Показание всегда несёт свою область: сколько стеков в области, сколько из них прочиталось, какой отрезок логов попал в хвост. Без этого «всё чисто» неотличимо от «половину не посмотрел», поэтому чего не смог - тоже в инжекте. """ from __future__ import annotations import hashlib import json import re from dataclasses import dataclass, field from datetime import UTC, datetime, timedelta, tzinfo from typing import TYPE_CHECKING, Any from beaver_agent.hands.komodo import ANSI if TYPE_CHECKING: from pathlib import Path __all__ = [ "SCOPE", "SIGNALS", "TAIL", "Entry", "Report", "Seen", "StackScan", "Sweep", "brief", "digest", "read_stack", ] SCOPE = ("dell-home", "personal-main") """Свои серверы. Машины заказчиков (md-cars-*, veris-*, ms-agents-*) не наши: там чужой прод и чужие секреты, и читать их логи в свой контекст - нельзя.""" TAIL = 500 """Строк на стек. Болтливый стек столько строк проживает за минуты - об этом в инжекте говорится отдельно, а не выдаётся за просмотренный промежуток.""" SIGNALS: tuple[tuple[str, str], ...] = ( ("критично", r"\bCRITICAL\b|\bFATAL\b|\bEMERG\b"), ("паника", r"\bpanic:|\bpanicked at\b|\bfatal error:"), ("oom", r"\bOOM\b|OOMKilled|[Oo]ut of memory|oom[-_]kill"), ("traceback", r"Traceback \(most recent call last\)|\bUnhandled exception\b"), ("падение", r"exited with code (?!0\b)\d+|\bexit status [1-9]|Exited \([1-9]\d*\)"), ("рестарт-цикл", r"[Rr]estarting \(\d+\)|back-?off.{0,20}restart|CrashLoopBackOff"), ("healthcheck", r"health-?\s?check (?:failed|error)|\bunhealthy\b"), ("ошибка", r"\bERROR\b|\bERR!\b"), ) """Что считается бедой: метка и выражение. Правится одним местом; порядок - приоритет, строка получает первую подошедшую метку.""" MATCHERS = tuple((label, re.compile(pattern)) for label, pattern in SIGNALS) SELF_MARK = "Логи флота" """Свой же инжект видно в stdout gateway: ловить себя по кругу не надо.""" LINE_RE = re.compile(r"^(?P[^\s|]+)\s*\|\s?(?P.*)$") STAMP_RE = re.compile( r"^(?P\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?Z)(?:\s(?P.*))?$" ) """Пустая строка тоже со штампом (`сервис | время` и ничего) - это не мусор.""" DIGITS_RE = re.compile(r"\b[0-9a-f]{7,}\b|\d+") """Числа и хеши в строке - шум: без них «то же самое» узнаётся между проходами.""" SECRET_RE = re.compile( r"(?i)\b(?:token|secret|api[-_ ]?key|password|passwd|authorization)\b\s*[=:]\s*\S+" r"|\b[A-Za-z0-9_\-]{32,}\b" ) """Инжект уезжает в чат и в vault: похожее на ключ в показании не нужно.""" SAMPLE_CHARS = 180 MAX_NEW = 25 MAX_QUIET = 10 MAX_TROUBLE = 10 GAP_NAMES = 3 UNPARSED_LOUD = 10 """Столько неразобранных строк на проход - уже не обрезанная голова, а дыра.""" KEEP = timedelta(days=14) """Сколько помнить беду, которой больше не видно: дальше пусть будет новой.""" KEY_CHARS = 12 STATE_VERSION = 1 EPOCH = datetime(1970, 1, 1, tzinfo=UTC) @dataclass(frozen=True, slots=True) class Hit: """Одна беда в хвосте одного стека, уже слитая по повторам.""" key: str stack: str service: str signal: str sample: str at: datetime | None count: int @dataclass(frozen=True, slots=True) class StackScan: """Что дал один стек: находки, отрезок его хвоста или причина отказа.""" stack: str hits: tuple[Hit, ...] = () first: datetime | None = None last: datetime | None = None lines: int = 0 unparsed: int = 0 """Строки без `сервис | время`: обрезанная голова хвоста и прочий мусор.""" error: str | None = None @property def ok(self) -> bool: return self.error is None @dataclass(frozen=True, slots=True) class Sweep: """Проход целиком - вместе с тем, какую область он покрыл.""" at: datetime scans: tuple[StackScan, ...] = () in_scope: int = 0 fleet: int = 0 summary: int | None = None tail: int = TAIL scope: tuple[str, ...] = SCOPE unreachable: str | None = None """Komodo не ответил вовсе - ни одного стека, и это не «чисто».""" @property def read(self) -> tuple[StackScan, ...]: return tuple(s for s in self.scans if s.ok) @property def trouble(self) -> tuple[str, ...]: if self.unreachable: return (f"Komodo не ответил: {self.unreachable}",) out = [f"{s.stack}: {s.error}" for s in self.scans if not s.ok] if self.summary is not None and self.summary != self.fleet: out.append( f"листание дало {self.fleet} стеков, а GetStacksSummary - " f"{self.summary}: список неполон" ) return tuple(out) @property def span(self) -> tuple[datetime | None, datetime | None]: """Отрезок, который реально попал в хвосты всех прочитанных стеков.""" firsts = [s.first for s in self.read if s.first] lasts = [s.last for s in self.read if s.last] return (min(firsts) if firsts else None, max(lasts) if lasts else None) @property def shortest(self) -> StackScan | None: """Стек с самым коротким хвостом: он и ограничивает, что мы видели.""" stamped = [s for s in self.read if s.first] if not stamped: return None return max(stamped, key=lambda s: s.first or EPOCH) def gaps(self, since: datetime | None) -> tuple[str, ...]: """Стеки, чей хвост начался позже прошлого прохода: там дыра.""" if since is None: return () return tuple(s.stack for s in self.read if s.first and s.first > since) @dataclass(slots=True) class Entry: """Беда, которую уже видели: когда впервые, когда последний раз, сколько раз.""" key: str stack: str service: str signal: str sample: str first: datetime | None = None last: datetime | None = None """Время события из строки лога, а не время прохода.""" looked: datetime | None = None """Когда её последний раз видели в хвосте: по этому и забываем.""" count: int = 0 told: bool = False """Сказали ли о ней мастеру. Инжект не доехал - не сказали, повторим.""" @property def where(self) -> str: return f"{self.stack}/{self.service}" @dataclass(frozen=True, slots=True) class Report: """Что из прохода стоит мастера.""" sweep: Sweep new: tuple[Entry, ...] = () quiet: tuple[Entry, ...] = () trouble: tuple[str, ...] = () gaps: tuple[str, ...] = () cold: bool = False """Первый проход: состояния не было, и вся область легла в базовую линию.""" baseline: int = 0 """Сколько бед легло в базовую линию в этом проходе.""" baselined: tuple[str, ...] = () """Стеки, впервые прочитанные в этом проходе: их прошлое не показывается.""" @property def worth_telling(self) -> bool: return bool(self.new or self.quiet or self.trouble or self.cold) @dataclass(slots=True) class Seen: """Состояние между проходами: файл на диске, переживает передеплой.""" path: Path entries: dict[str, Entry] = field(default_factory=dict) baselined: set[str] = field(default_factory=set) """Стеки, чьё прошлое уже принято за данность: их старое не «новое».""" trouble: tuple[str, ...] = () """О каких отказах уже сказали: Komodo лежит - скажем один раз, не каждые 3 ч.""" last_pass: datetime | None = None fresh: bool = True """Файла не было: базовую линию только снимаем, стену старых бед не шлём.""" @classmethod def load(cls, path: Path) -> Seen: try: raw = json.loads(path.read_text(encoding="utf-8")) except (OSError, ValueError): return cls(path=path) if raw.get("version") != STATE_VERSION: return cls(path=path) entries = { key: Entry( key=key, stack=row["stack"], service=row["service"], signal=row["signal"], sample=row["sample"], first=_parse(row.get("first")), last=_parse(row.get("last")), looked=_parse(row.get("looked")), count=int(row.get("count", 0)), told=bool(row.get("told")), ) for key, row in raw.get("entries", {}).items() } return cls( path=path, entries=entries, baselined=set(raw.get("baselined", ())), trouble=tuple(raw.get("trouble", ())), last_pass=_parse(raw.get("last_pass")), fresh=False, ) def save(self) -> None: body = { "version": STATE_VERSION, "last_pass": _iso(self.last_pass), "baselined": sorted(self.baselined), "trouble": list(self.trouble), "entries": { key: { "stack": e.stack, "service": e.service, "signal": e.signal, "sample": e.sample, "first": _iso(e.first), "last": _iso(e.last), "looked": _iso(e.looked), "count": e.count, "told": e.told, } for key, e in self.entries.items() }, } self.path.parent.mkdir(parents=True, exist_ok=True) tmp = self.path.with_suffix(".tmp") tmp.write_text(json.dumps(body, ensure_ascii=False), encoding="utf-8") tmp.replace(self.path) def mark_told(self, report: Report) -> None: """Инжект доехал: новое больше не новое, стихшее забывается.""" for entry in report.new: entry.told = True for entry in report.quiet: self.entries.pop(entry.key, None) self.trouble = report.trouble def _iso(at: datetime | None) -> str | None: return at.isoformat() if at else None def _parse(raw: Any) -> datetime | None: if not isinstance(raw, str): return None try: at = datetime.fromisoformat(raw) except ValueError: return None return at if at.tzinfo else at.replace(tzinfo=UTC) def _mask(text: str) -> str: """Замазать похожее на секрет: строка лога едет мастеру как есть.""" return SECRET_RE.sub("<скрыто>", text) def _normal(text: str) -> str: """Строка без чисел, хешей и адресов: по ней узнаётся «та же самая беда».""" return DIGITS_RE.sub("#", ANSI.sub("", text)).strip() def _key(stack: str, service: str, text: str) -> str: raw = f"{stack}\0{service}\0{_normal(text)}".encode() return hashlib.blake2s(raw, digest_size=KEY_CHARS // 2).hexdigest() def signal_of(text: str) -> str | None: for label, matcher in MATCHERS: if matcher.search(text): return label return None def read_stack(stack: str, log: dict[str, Any]) -> StackScan: """Ответ GetStackLog → находки стека; ошибка Komodo остаётся ошибкой.""" if not isinstance(log, dict) or "error" in log: error = log.get("error") if isinstance(log, dict) else "ответ не разобран" return StackScan(stack=stack, error=str(error)[:200]) text = (log.get("stdout") or "") + "\n" + (log.get("stderr") or "") found: dict[str, Hit] = {} stamps: list[datetime] = [] lines = 0 unparsed = 0 for raw in text.splitlines(): line = ANSI.sub("", raw).strip() if not line: continue match = LINE_RE.match(line) stamped = STAMP_RE.match(match.group("rest")) if match else None if match is None or stamped is None: # Голову хвоста Komodo обрезает по месту, и от прохода к проходу она # разная: недоразобранная строка - не находка, иначе каждый раз «ново». unparsed += 1 continue lines += 1 service = match.group("service") at = datetime.fromisoformat(stamped.group("ts")).astimezone(UTC) stamps.append(at) rest = stamped.group("text") or "" if SELF_MARK in rest: continue signal = signal_of(rest) if signal is None: continue key = _key(stack, service, rest) before = found.get(key) found[key] = Hit( key=key, stack=stack, service=service, signal=signal, sample=(before.sample if before else _mask(rest)[:SAMPLE_CHARS]), at=at or (before.at if before else None), count=(before.count if before else 0) + 1, ) return StackScan( stack=stack, hits=tuple(found.values()), first=min(stamps) if stamps else None, last=max(stamps) if stamps else None, lines=lines, unparsed=unparsed, ) def _forget(seen: Seen, now: datetime) -> None: """Беду, которой давно не видно в хвостах, забываем: вернётся - будет новой. Считаем по времени прохода, в котором её видели, а не по времени события: строка от прошлого месяца может спокойно лежать в хвосте тихого стека, и забывать её - значит каждый проход объявлять её новой. """ for key, entry in list(seen.entries.items()): if entry.told and entry.looked is not None and now - entry.looked > KEEP: del seen.entries[key] def digest(seen: Seen, sweep: Sweep) -> Report: """Сравнить проход с прошлым: что новое, что стихло, о чём молчать.""" gaps = sweep.gaps(seen.last_pass) _forget(seen, sweep.at) 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} baseline = 0 for key, hit in hits.items(): entry = seen.entries.get(key) if entry is None: entry = Entry( key=key, stack=hit.stack, service=hit.service, signal=hit.signal, sample=hit.sample, first=hit.at or sweep.at, looked=sweep.at, ) seen.entries[key] = entry if hit.stack in newcomers: # Стек читаем впервые: в хвосте лежит всё его прошлое, и вываливать # его как «новое» - врать. Принимаем за данность, дальше - только рост. entry.told = True baseline += 1 entry.last = hit.at or entry.last or sweep.at entry.looked = sweep.at entry.count += hit.count seen.baselined |= looked # Стихло - только у стеков, которые прочитались: чего не видели, того не судим. quiet = tuple( e for e in seen.entries.values() if e.told and e.stack in looked and e.key not in hits ) seen.last_pass = sweep.at # Холодный старт без единого прочитанного стека базой не считается: иначе # первый удачный проход вывалит всю область как «новое». cold = seen.fresh and bool(sweep.read) seen.fresh = seen.fresh and not sweep.read fresh = tuple(e for e in seen.entries.values() if not e.told) trouble = sweep.trouble if sweep.trouble != seen.trouble else () return Report( sweep=sweep, new=tuple(sorted(fresh, key=lambda e: (e.stack, e.service))), quiet=tuple(sorted(quiet, key=lambda e: (e.stack, e.service))), trouble=trouble, gaps=gaps, cold=cold, baseline=baseline, baselined=tuple(sorted(newcomers)), ) def _when(at: datetime | None, tz: tzinfo) -> str: return at.astimezone(tz).strftime("%d.%m %H:%M") if at else "время не в строке" def _scope_line(sweep: Sweep, gaps: tuple[str, ...], tz: tzinfo) -> str: since, until = sweep.span where = ", ".join(sweep.scope) if sweep.unreachable: return f"Область: {where} - не прочитано ничего, списка стеков нет." out = [ ( f"Область: {where} - прочитано {len(sweep.read)} стеков из " f"{sweep.in_scope} в области (во флоте {sweep.fleet})" ), ( f"хвост {sweep.tail} строк на стек: строки с {_when(since, tz)} " f"по {_when(until, tz)}" ), ] short = sweep.shortest if short is not None: out.append( f"самый короткий хвост у {short.stack} - только с {_when(short.first, tz)}" ) blind = sum(s.unparsed for s in sweep.read) if blind > UNPARSED_LOUD: out.append(f"строк без метки времени пропущено {blind} - их не смотрел") if gaps: names = ", ".join(gaps[:GAP_NAMES]) more = f" и ещё {len(gaps) - GAP_NAMES}" if len(gaps) > GAP_NAMES else "" out.append( f"у {len(gaps)} стеков хвост начался позже прошлого прохода " f"({names}{more}) - между проходами часть строк прошла мимо" ) return "; ".join(out) + "." def _entry_line(entry: Entry, tz: tzinfo, *, new: bool) -> str: when = _when(entry.last, tz) times = f" ×{entry.count}" if entry.count > 1 else "" head = f"- {entry.where} {when}{times} {entry.signal}: " if not new: head = f"- {entry.where} {entry.signal}, последнее в {when}: " return head + entry.sample def brief(report: Report, tz: tzinfo = UTC) -> str: """Инжект: что нового, где, сколько раз - и всегда область просмотра.""" sweep = report.sweep lines = [f"{SELF_MARK}: проход {sweep.at.astimezone(tz):%d.%m %H:%M}."] lines.append(_scope_line(sweep, report.gaps, tz)) if report.cold: lines.append( f"Первый проход: снял базовую линию, в хвостах {report.baseline} " "таких строк - дальше дёргаю только тем, чего в прошлом проходе не было." ) elif report.baselined: names = ", ".join(report.baselined[:GAP_NAMES]) more = ( f" и ещё {len(report.baselined) - GAP_NAMES}" if len(report.baselined) > GAP_NAMES else "" ) lines.append( f"Впервые прочитаны ({report.baseline} строк в базу): {names}{more} - " "их прошлое принял за данность, показываю только то, что появится дальше." ) if report.new: lines.append(f"Новое ({len(report.new)}):") lines.extend(_entry_line(e, tz, new=True) for e in report.new[:MAX_NEW]) if len(report.new) > MAX_NEW: lines.append(f"…и ещё {len(report.new) - MAX_NEW} - смотри komodo(logs).") elif not report.cold and sweep.read: lines.append("Нового в этой области нет.") if report.quiet: lines.append(f"Стихло ({len(report.quiet)}), время - события, не прохода:") lines.extend(_entry_line(e, tz, new=False) for e in report.quiet[:MAX_QUIET]) if len(report.quiet) > MAX_QUIET: lines.append(f"…и ещё {len(report.quiet) - MAX_QUIET}.") if report.trouble: lines.append(f"Не смог посмотреть ({len(report.trouble)}):") lines.extend(f"- {t}" for t in report.trouble[:MAX_TROUBLE]) lines.append("Это только чтение: чинить или забить - решаешь ты.") return "\n".join(lines)