Skip to content

Commit 3fc801a

Browse files
committed
boot log waterfall
1 parent 2ea08fe commit 3fc801a

22 files changed

Lines changed: 1715 additions & 191 deletions

File tree

‎robot_orchestrator/boot/fsm.py‎

Lines changed: 190 additions & 51 deletions
Large diffs are not rendered by default.
Lines changed: 117 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,117 @@
1+
import threading
2+
import time
3+
from dataclasses import dataclass
4+
5+
from robot_orchestrator.bootlog import BOOT_LOG, BootEventLog
6+
7+
PENDING = "pending"
8+
RUNNING = "running"
9+
OK = "ok"
10+
WARN = "warn"
11+
FAILED = "failed"
12+
SKIPPED = "skipped"
13+
14+
TERMINAL = {OK, WARN, FAILED, SKIPPED}
15+
16+
DEFAULT_STEPS: list[tuple[str, str]] = [
17+
("init", "Инициализация"),
18+
("recover", "Восстановление журнала"),
19+
("gpio", "Перемычка GPIO"),
20+
("secrets", "Секреты"),
21+
("qr", "Сканирование QR-кода"),
22+
("camera", "Камера"),
23+
("microphone", "Микрофон"),
24+
("network", "Сеть и интернет"),
25+
("tooling", "Инструменты прошивки"),
26+
("mcu", "ST-Link и микроконтроллер"),
27+
("repos", "Обновление репозиториев"),
28+
("firmware", "Прошивка микроконтроллера"),
29+
("mode", "Определение режима"),
30+
("services", "Запуск сервисов"),
31+
("handoff", "Запуск интерфейса"),
32+
]
33+
34+
_LEVEL_FOR_STATUS = {OK: "ok", WARN: "warn", FAILED: "error", SKIPPED: "dim"}
35+
_MARK_FOR_STATUS = {OK: "✔", WARN: "⚠", FAILED: "✖", SKIPPED: "–"}
36+
37+
38+
@dataclass
39+
class BootStep:
40+
id: str
41+
title: str
42+
status: str = PENDING
43+
detail: str = ""
44+
started_at: float | None = None
45+
finished_at: float | None = None
46+
47+
def to_dict(self) -> dict:
48+
return {
49+
"id": self.id, "title": self.title, "status": self.status, "detail": self.detail,
50+
"started_at": self.started_at, "finished_at": self.finished_at,
51+
}
52+
53+
54+
class BootProgress:
55+
def __init__(self, log: BootEventLog | None = None, steps: list[tuple[str, str]] | None = None):
56+
self.log = log or BOOT_LOG
57+
self.steps = [BootStep(step_id, title) for step_id, title in (steps or DEFAULT_STEPS)]
58+
self._by_id = {step.id: step for step in self.steps}
59+
self.step = "starting"
60+
self.started_at = time.time()
61+
self.finished_at: float | None = None
62+
self._lock = threading.Lock()
63+
64+
def begin(self, step_id: str, detail: str = "") -> None:
65+
with self._lock:
66+
step = self._by_id[step_id]
67+
step.status = RUNNING
68+
step.detail = detail
69+
step.started_at = time.time()
70+
step.finished_at = None
71+
self.step = step_id
72+
title = step.title
73+
self.log.emit("boot", f"▶ {title}" + (f" — {detail}" if detail else ""), "step")
74+
75+
def update(self, step_id: str, detail: str) -> None:
76+
with self._lock:
77+
self._by_id[step_id].detail = detail
78+
79+
def finish(self, step_id: str, status: str = OK, detail: str = "") -> None:
80+
with self._lock:
81+
step = self._by_id[step_id]
82+
step.status = status
83+
if detail:
84+
step.detail = detail
85+
now = time.time()
86+
step.started_at = step.started_at or now
87+
step.finished_at = now
88+
title, final_detail = step.title, step.detail
89+
text = f"{_MARK_FOR_STATUS.get(status, '•')} {title}" + (f" — {final_detail}" if final_detail else "")
90+
self.log.emit("boot", text, _LEVEL_FOR_STATUS.get(status, "info"))
91+
92+
def skip(self, step_id: str, detail: str = "") -> None:
93+
self.finish(step_id, SKIPPED, detail)
94+
95+
def note(self, text: str, level: str = "info", source: str = "boot") -> None:
96+
self.log.emit(source, text, level)
97+
98+
def complete(self) -> None:
99+
with self._lock:
100+
self.finished_at = time.time()
101+
self.step = "done"
102+
103+
def snapshot(self) -> dict:
104+
with self._lock:
105+
steps = [step.to_dict() for step in self.steps]
106+
now = time.time()
107+
end = self.finished_at or now
108+
finished = sum(1 for step in self.steps if step.status in TERMINAL)
109+
running = sum(1 for step in self.steps if step.status == RUNNING)
110+
percent = round(100 * (finished + 0.5 * running) / len(self.steps))
111+
return {
112+
"step": self.step,
113+
"steps": steps,
114+
"started_at": self.started_at,
115+
"elapsed": round(end - self.started_at, 1),
116+
"percent": 100 if self.finished_at else min(percent, 99),
117+
}

‎robot_orchestrator/bootlog.py‎

Lines changed: 212 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,212 @@
1+
import collections
2+
import logging
3+
import re
4+
import subprocess
5+
import threading
6+
import time
7+
import uuid
8+
from typing import Callable
9+
10+
_ANSI_RE = re.compile(r"\x1b\[[0-9;?]*[a-zA-Z]")
11+
_ERROR_RE = re.compile(r"\b(error|traceback|fatal|exception|failed|segmentation fault|critical)\b", re.IGNORECASE)
12+
_WARN_RE = re.compile(r"\b(warn|warning|deprecated|retry|retrying)\b", re.IGNORECASE)
13+
_MAX_LINE = 600
14+
15+
16+
_URL_USERINFO_RE = re.compile(r"(\b[a-zA-Z][a-zA-Z0-9+.\-]*://)([^/\s:@]+):([^@\s/]+)@")
17+
_QUERY_SECRET_RE = re.compile(
18+
r"([?&](?:token|key|api_key|apikey|access_token|password|passwd|psk|secret)=)[^&\s\"']+", re.IGNORECASE
19+
)
20+
_KV_SECRET_RE = re.compile(
21+
r"\b(password|passwd|psk|secret|token|api_key|apikey)\b(\s*[=:]\s*)(\"?)[^\s\"',;]+", re.IGNORECASE
22+
)
23+
_BEARER_RE = re.compile(r"(\bBearer\s+)[A-Za-z0-9._~+/=\-]+", re.IGNORECASE)
24+
_MASK = "••••"
25+
26+
27+
def strip_ansi(text: str) -> str:
28+
return _ANSI_RE.sub("", text)
29+
30+
31+
def redact(text: str, known_secrets: tuple[str, ...] = ()) -> str:
32+
"""Hide credentials before a line can reach a screen or a network client."""
33+
for secret in known_secrets:
34+
if secret in text:
35+
text = text.replace(secret, _MASK)
36+
text = _URL_USERINFO_RE.sub(r"\1***:***@", text)
37+
text = _QUERY_SECRET_RE.sub(rf"\1{_MASK}", text)
38+
text = _KV_SECRET_RE.sub(rf"\1\2\3{_MASK}", text)
39+
return _BEARER_RE.sub(rf"\1{_MASK}", text)
40+
41+
42+
def classify_level(text: str, default: str = "info") -> str:
43+
if _ERROR_RE.search(text):
44+
return "error"
45+
if _WARN_RE.search(text):
46+
return "warn"
47+
return default
48+
49+
50+
class BootEventLog:
51+
"""Thread-safe ring buffer of boot events that any number of consumers can follow live."""
52+
53+
def __init__(self, max_events: int = 4000):
54+
self.epoch = uuid.uuid4().hex[:12]
55+
self._events: collections.deque[dict] = collections.deque(maxlen=max_events)
56+
self._seq = 0
57+
self._lock = threading.Lock()
58+
self._subscribers: list[Callable[[dict], None]] = []
59+
self._known_secrets: tuple[str, ...] = ()
60+
61+
def set_known_secrets(self, values) -> None:
62+
cleaned = {str(v) for v in values if v and len(str(v)) >= 6}
63+
self._known_secrets = tuple(sorted(cleaned, key=len, reverse=True))
64+
65+
def emit(self, source: str, text: str, level: str = "info") -> dict | None:
66+
text = redact(strip_ansi(text).rstrip(), self._known_secrets)
67+
if not text:
68+
return None
69+
if len(text) > _MAX_LINE:
70+
text = text[:_MAX_LINE] + "…"
71+
with self._lock:
72+
self._seq += 1
73+
event = {"seq": self._seq, "ts": time.time(), "source": source, "level": level, "text": text}
74+
self._events.append(event)
75+
subscribers = list(self._subscribers)
76+
for callback in subscribers:
77+
try:
78+
callback(event)
79+
except Exception:
80+
pass
81+
return event
82+
83+
def tail(self, after_seq: int = 0, limit: int = 500) -> list[dict]:
84+
with self._lock:
85+
events = [e for e in self._events if e["seq"] > after_seq]
86+
return events[-limit:]
87+
88+
def subscribe(self, callback: Callable[[dict], None]) -> None:
89+
with self._lock:
90+
self._subscribers.append(callback)
91+
92+
def unsubscribe(self, callback: Callable[[dict], None]) -> None:
93+
with self._lock:
94+
if callback in self._subscribers:
95+
self._subscribers.remove(callback)
96+
97+
@property
98+
def last_seq(self) -> int:
99+
with self._lock:
100+
return self._seq
101+
102+
103+
BOOT_LOG = BootEventLog()
104+
105+
106+
def forward_service_line(name: str, raw: str, log: BootEventLog | None = None) -> None:
107+
"""Mirror a LogSink line ('<ts> <stream> <text>') into the boot event log."""
108+
from robot_orchestrator.supervisor.logsink import parse_line
109+
110+
parsed = parse_line(name, raw)
111+
(log or BOOT_LOG).emit(name, parsed["text"], classify_level(parsed["text"]))
112+
113+
114+
class BootLogHandler(logging.Handler):
115+
"""Forwards orchestrator log records (not uvicorn/asyncio chatter) to the boot event log."""
116+
117+
def __init__(self, log: BootEventLog | None = None):
118+
super().__init__(level=logging.INFO)
119+
self._log = log or BOOT_LOG
120+
121+
def emit(self, record: logging.LogRecord) -> None:
122+
if record.name.startswith(("uvicorn", "asyncio", "http")):
123+
return
124+
try:
125+
level = {"WARNING": "warn", "ERROR": "error", "CRITICAL": "error"}.get(record.levelname, "info")
126+
self._log.emit("orchestrator", record.getMessage(), level)
127+
except Exception:
128+
pass
129+
130+
131+
def _mask_values(text: str, mask: tuple[str, ...]) -> str:
132+
for value in mask:
133+
if value:
134+
text = text.replace(value, _MASK)
135+
return text
136+
137+
138+
def _pump(stream, source: str, sink: list[str], log: BootEventLog, mask: tuple[str, ...]) -> None:
139+
last = None
140+
try:
141+
for raw in stream:
142+
sink.append(raw)
143+
line = _mask_values(strip_ansi(raw).rstrip(), mask)
144+
if not line or line == last:
145+
continue
146+
last = line
147+
log.emit(source, line, classify_level(line))
148+
except (ValueError, OSError):
149+
pass
150+
151+
152+
def _describe(argv, mask: tuple[str, ...] = ()) -> str:
153+
text = argv if isinstance(argv, str) else " ".join(str(part) for part in argv)
154+
text = _mask_values(text, mask)
155+
return text if len(text) <= 240 else text[:237] + "..."
156+
157+
158+
def logged_run(
159+
argv,
160+
*,
161+
source: str,
162+
cwd=None,
163+
env=None,
164+
timeout: float | None = None,
165+
check: bool = False,
166+
shell: bool = False,
167+
announce: bool = True,
168+
mask: tuple[str, ...] = (),
169+
log: BootEventLog | None = None,
170+
) -> subprocess.CompletedProcess:
171+
"""Drop-in for subprocess.run(capture_output=True, text=True) that also streams every output line live."""
172+
log = log or BOOT_LOG
173+
if announce:
174+
log.emit(source, f"$ {_describe(argv, mask)}", "cmd")
175+
176+
process = subprocess.Popen(
177+
argv, cwd=cwd, env=env, shell=shell,
178+
stdout=subprocess.PIPE, stderr=subprocess.PIPE,
179+
text=True, encoding="utf-8", errors="replace", bufsize=1,
180+
)
181+
out_lines: list[str] = []
182+
err_lines: list[str] = []
183+
threads = [
184+
threading.Thread(target=_pump, args=(process.stdout, source, out_lines, log, mask), daemon=True),
185+
threading.Thread(target=_pump, args=(process.stderr, source, err_lines, log, mask), daemon=True),
186+
]
187+
for thread in threads:
188+
thread.start()
189+
190+
try:
191+
process.wait(timeout=timeout)
192+
except subprocess.TimeoutExpired:
193+
process.kill()
194+
process.wait()
195+
for thread in threads:
196+
thread.join(timeout=2.0)
197+
log.emit(source, f"таймаут {timeout}s: процесс убит", "error")
198+
raise subprocess.TimeoutExpired(argv, timeout, output="".join(out_lines), stderr="".join(err_lines))
199+
except BaseException:
200+
process.kill()
201+
process.wait()
202+
raise
203+
204+
for thread in threads:
205+
thread.join(timeout=5.0)
206+
207+
stdout, stderr = "".join(out_lines), "".join(err_lines)
208+
if announce and process.returncode != 0:
209+
log.emit(source, f"завершилось с кодом {process.returncode}", "error")
210+
if check and process.returncode != 0:
211+
raise subprocess.CalledProcessError(process.returncode, argv, output=stdout, stderr=stderr)
212+
return subprocess.CompletedProcess(argv, process.returncode, stdout, stderr)

0 commit comments

Comments
 (0)