diff --git a/Makefile b/Makefile index 1cc8d99..5eee313 100644 --- a/Makefile +++ b/Makefile @@ -136,9 +136,23 @@ ifdef MX_CHAIN_GO_DIR RESTART_ARGS += --mx-chain-go-dir $(MX_CHAIN_GO_DIR) endif +LOGSTATS_ARGS := +ifdef NODE +LOGSTATS_ARGS += --node $(NODE) +endif +ifdef ERROR_LINES +LOGSTATS_ARGS += --max-errors $(ERROR_LINES) +endif +ifdef WARN_LINES +LOGSTATS_ARGS += --max-warns $(WARN_LINES) +endif +ifdef MX_CHAIN_GO_DIR +LOGSTATS_ARGS += --mx-chain-go-dir $(MX_CHAIN_GO_DIR) +endif + LOG_FILES = "$(TESTNETDIR)"/logs/*.log -.PHONY: start stop status logs clean klogg test help tx-gen stop-tx-gen restart +.PHONY: start stop status logs log-stats clean klogg test help tx-gen stop-tx-gen restart start: ## Start the testnet (seednode + validators + proxy). $(PYTHON) $(SRC)/start.py $(START_ARGS) @@ -155,7 +169,7 @@ stop-tx-gen: ## Stop only txgen (leave the testnet running). stop: ## Gracefully stop the testnet. $(PYTHON) $(SRC)/stop.py -status: ## Show whether the testnet processes are running. +status: ## Show processes with live round/nonce/epoch. $(PYTHON) $(SRC)/status.py logs: ## Show the tail of every testnet log file. @@ -172,6 +186,9 @@ logs: ## Show the tail of every testnet log file. exit 1; \ fi +log-stats: ## Counts per log file + ERROR/WARN lines (NODE=x, ERROR_LINES/WARN_LINES=0 to hide). + $(PYTHON) $(SRC)/logstats.py $(LOGSTATS_ARGS) + clean: stop ## Stop the testnet and delete the whole testnet directory. @if [ -z "$(TESTNETDIR)" ]; then echo "TESTNETDIR is empty, refusing to clean."; exit 1; fi @echo "Removing $(TESTNETDIR)..." diff --git a/README.md b/README.md index bcc479d..b2fbbb8 100644 --- a/README.md +++ b/README.md @@ -162,8 +162,15 @@ scratch testnet. make status ``` -Prints one line per expected process (`RUNNING (pid …)` / `STOPPED`). -Exits 0 when everything is up, 1 otherwise. +Prints one line per expected process (`RUNNING (pid …)` / `STOPPED`) +with per-node details: validators show their role (`meta` / `shard N`), +p2p and REST ports, plus their live `round`/`nonce`/`epoch` probed from +the REST API. The role comes from the node's self-reported shard id when +reachable, so labels stay right even if status runs with different flags +than start; proxy shows its URL, seednode/txgen show no extra detail — +a failed validator/proxy probe (`api DOWN`) still prints and exits 1, +catching processes that are alive but wedged. Probes run +concurrently, so the worst case is ~one timeout, not one per process. ## How to restart a node @@ -192,8 +199,16 @@ flag run normally again. ```sh make logs # tail of every log file +make log-stats # level counts per file + ERROR/WARN lines +make log-stats NODE=validator2 # only one node's log file +make log-stats ERROR_LINES=0 WARN_LINES=0 # counts only, hide lines ``` +`log-stats` understands plain lines (`INFO [...]`) and proxy-style +lines (`ERROR[...]`). `launcher.log` (the tool's own output) is always +skipped. Anything without a leading level — Go stack traces, ASCII +tables, `[GIN-debug]` gin chatter — lands in `OTHER`. + - Every process logs to `/logs/.log` (`validator.log`, `seednode.log`, `proxy.log`, `txgen.log`; `launcher.log` captures this tool's own output) @@ -224,7 +239,7 @@ when the mx-chain-go checkout is absent. ## Project layout ```text -Makefile start/stop/status/logs/clean/klogg/test/tx-gen/stop-tx-gen/restart +Makefile start/stop/status/logs/log-stats/clean/klogg/test/tx-gen/stop-tx-gen/restart requirements.txt stdlib only — nothing to install README.md this file src/ @@ -240,6 +255,7 @@ src/ start.py CLI + orchestration (build → generate → configure → launch) stop.py CLI + stop orchestration (also reused by start --clean) status.py CLI status report + logstats.py CLI log-level counts per file (used by log-stats) restart.py single-node graceful restart (interactive list or --node) txgen.py CLI + txgen orchestration (build → configure → launch) tests/ diff --git a/src/logstats.py b/src/logstats.py new file mode 100644 index 0000000..ba62648 --- /dev/null +++ b/src/logstats.py @@ -0,0 +1,239 @@ +#!/usr/bin/env python3 +"""Count log levels per testnet log file. + +Scans ``/logs/*.log`` line by line (log files can be GBs, so +nothing is loaded fully into memory) and prints one row per file with +the number of ``ERROR`` / ``WARN`` / ``INFO`` / ``DEBUG`` / ``TRACE`` +lines plus a ``TOTAL`` row. When ``ERROR`` or ``WARN`` lines exist, they +are printed as well (capped per file, longest lines trimmed), so a +failing testnet shows what broke without opening klogg. + +Node log lines look like:: + + ERROR [2025-04-29 07:46:37.102] [logger] [shard/epoch/round/...] message + +and the proxy omits the space (``ERROR[...]``). Only a leading level +token counts: an ``ERROR`` appearing inside a message body, a Go stack +trace, an ASCII table row or a ``[GIN-debug]`` gin-framework line does +not, and falls into ``OTHER``. + +``launcher.log`` (the tool's own orchestration output) is always +skipped. + +Exit code is 0 even when errors are found (this is a report, not a +health check); 1 only when there are no log files to scan. +""" + +from __future__ import annotations + +import argparse +import glob +import logging +import os +import re +import sys +from typing import Dict, List, Optional + +import config + +LOG = logging.getLogger("logstats") + +LEVELS = ("ERROR", "WARN", "INFO", "DEBUG", "TRACE") + +_LINE_RE = re.compile(r"^(ERROR|WARN|INFO|DEBUG|TRACE)\s*\[") + + +def level_of(line: str): + """Return the log level of one line, or None when it has none. + + Only a leading ``LEVEL [...]`` token counts; the ``launcher.log`` + Python-logging format is not recognised (that file is the tool's + own output and is skipped by the scanner). + """ + match = _LINE_RE.match(line) + if match: + return match.group(1) + return None + +# Lines shown per file for the ERROR/WARN report sections +# (longest lines trimmed to MAX_ERROR_LINE_LEN). +MAX_ERRORS_PER_FILE = 20 +MAX_ERROR_LINE_LEN = 500 + + +def parse_args(argv: Optional[List[str]] = None) -> argparse.Namespace: + parser = argparse.ArgumentParser(description="Count log levels per file.") + parser.add_argument("--node", default=None, metavar="NAME", + help="only scan one log file " + "(e.g. validator2, proxy, seednode)") + parser.add_argument("--max-errors", type=int, default=MAX_ERRORS_PER_FILE, + metavar="N", + help="ERROR lines printed per file " + "(default: %(default)s, 0 disables)") + parser.add_argument("--max-warns", type=int, default=MAX_ERRORS_PER_FILE, + metavar="N", + help="WARN lines printed per file " + "(default: %(default)s, 0 disables)") + parser.add_argument("--testnet-dir", default=None) + parser.add_argument("--mx-chain-go-dir", default=None, + help="mx-chain-go checkout to drive " + "(default: auto-detect sibling checkouts)") + return parser.parse_args(argv) + + +def count_levels(path: str) -> Dict[str, int]: + """Return ``{level: count}`` for one log file (streamed, never raises).""" + counts: Dict[str, int] = {level: 0 for level in LEVELS} + counts["OTHER"] = 0 + try: + with open(path, "r", encoding="utf-8", errors="replace") as handle: + for line in handle: + level = level_of(line) + if level is not None: + counts[level] += 1 + elif line.strip(): + counts["OTHER"] += 1 + except OSError as exc: + LOG.warning("cannot read %s: %s", path, exc) + return counts + + +def _resolve_paths(log_dir: str, node: Optional[str] = None) -> List[str]: + """Return sorted log paths to scan (single-file when ``node`` is set). + + ``launcher.log`` (the tool's own orchestration output) is always + excluded — it is not useful for diagnosing node issues. + """ + if node: + paths = [os.path.join(log_dir, "%s.log" % node)] + return [p for p in paths if os.path.isfile(p)] + return sorted( + p for p in glob.glob(os.path.join(log_dir, "*.log")) + if os.path.basename(p) != "launcher.log" + ) + + +def collect_counts(log_dir: str, node: Optional[str] = None): + """Return ``[(filename, counts)]`` sorted by filename.""" + return [(os.path.basename(p), count_levels(p)) + for p in _resolve_paths(log_dir, node)] + + +def collect_level_lines(log_dir: str, node: Optional[str] = None, + level: str = "ERROR", + max_per_file: int = MAX_ERRORS_PER_FILE): + """Return ``[(filename, lines, hidden)]`` for files with ``level`` lines. + + ``lines`` holds up to ``max_per_file`` raw lines (stripped of the + trailing newline, overlong lines trimmed); ``hidden`` is the number + of further lines not shown. Files without such lines are skipped. + Streamed one pass per file; never raises. + """ + rows = [] + for path in _resolve_paths(log_dir, node): + lines: List[str] = [] + hidden = 0 + try: + with open(path, "r", encoding="utf-8", errors="replace") as handle: + for line in handle: + if level_of(line) != level: + continue + if len(lines) < max_per_file: + lines.append(_trim_line(line)) + else: + hidden += 1 + except OSError as exc: + LOG.warning("cannot read %s: %s", path, exc) + continue + if lines or hidden: + rows.append((os.path.basename(path), lines, hidden)) + return rows + + +def collect_error_lines(log_dir: str, node: Optional[str] = None, + max_per_file: int = MAX_ERRORS_PER_FILE): + """Return ``[(filename, lines, hidden)]`` for files containing ERRORs.""" + return collect_level_lines(log_dir, node, level="ERROR", + max_per_file=max_per_file) + + +def _trim_line(line: str, limit: int = MAX_ERROR_LINE_LEN) -> str: + """Strip one log line, trimming overlong lines with an ellipsis.""" + line = line.rstrip("\n") + if len(line) > limit: + return line[:limit] + "..." + return line + + +def render(rows) -> str: + """Render the counts table (per-file rows plus a TOTAL row).""" + total: Dict[str, int] = {level: 0 for level in LEVELS} + total["OTHER"] = 0 + for _name, counts in rows: + for level in list(LEVELS) + ["OTHER"]: + total[level] += counts.get(level, 0) + header = "%-18s %7s %7s %7s %7s %7s %7s" % ( + "log file", "ERROR", "WARN", "INFO", "DEBUG", "TRACE", "OTHER") + lines = [header] + for name, counts in rows: + lines.append("%-18s %7d %7d %7d %7d %7d %7d" % ( + name, counts["ERROR"], counts["WARN"], counts["INFO"], + counts["DEBUG"], counts["TRACE"], counts["OTHER"])) + lines.append("%-18s %7d %7d %7d %7d %7d %7d" % ( + "TOTAL", total["ERROR"], total["WARN"], total["INFO"], + total["DEBUG"], total["TRACE"], total["OTHER"])) + return "\n".join(lines) + + +def render_errors(rows, level: str = "ERROR") -> str: + """Render collected ERROR/WARN lines grouped by file.""" + out = ["", "%s lines:" % level] + for name, lines, hidden in rows: + out.append("=== %s ===" % name) + out.extend(lines) + if hidden: + out.append("... and %d more %s lines in %s" % (hidden, level, name)) + return "\n".join(out) + + +def main(argv: Optional[List[str]] = None) -> int: + args = parse_args(argv) + try: + cfg = config.load_config({ + "testnet_dir": args.testnet_dir, + "mx_chain_go_dir": args.mx_chain_go_dir, + }) + except config.ConfigError as exc: + print("error: %s" % exc, file=sys.stderr) + return 1 + + print("testnet dir: %s" % cfg.testnet_dir) + rows = collect_counts(cfg.log_dir, node=args.node) + if not rows: + if args.node: + print("no log file for %r under %s." % (args.node, cfg.log_dir)) + else: + print("no log files under %s yet. Run 'make start' first." + % cfg.log_dir) + return 1 + print(render(rows)) + if args.max_errors > 0: + error_rows = collect_error_lines( + cfg.log_dir, node=args.node, max_per_file=args.max_errors) + if error_rows: + print(render_errors(error_rows)) + if args.max_warns > 0: + warn_rows = collect_level_lines( + cfg.log_dir, node=args.node, level="WARN", + max_per_file=args.max_warns) + if warn_rows: + print(render_errors(warn_rows, level="WARN")) + return 0 + + +if __name__ == "__main__": + logging.basicConfig( + level=logging.WARNING, + format="%(asctime)s %(levelname)-5s [%(name)s] %(message)s", + ) + sys.exit(main()) diff --git a/src/restart.py b/src/restart.py index 81ab09e..02a9e87 100644 --- a/src/restart.py +++ b/src/restart.py @@ -310,12 +310,7 @@ def main(argv: Optional[List[str]] = None) -> int: print("error: %s" % exc, file=sys.stderr) return 1 - os.makedirs(cfg.log_dir, exist_ok=True) - file_handler = logging.FileHandler( - os.path.join(cfg.log_dir, "launcher.log"), encoding="utf-8") - file_handler.setFormatter(logging.Formatter( - "%(asctime)s %(levelname)-5s [%(name)s] %(message)s")) - logging.getLogger().addHandler(file_handler) + services.setup_launcher_log(cfg) try: if args.node: diff --git a/src/services.py b/src/services.py index d8ac073..6853bc4 100644 --- a/src/services.py +++ b/src/services.py @@ -18,6 +18,7 @@ from __future__ import annotations +import logging import os import time from typing import Dict, List, Tuple @@ -47,6 +48,10 @@ def node_argv( "-sk-index", str(index), "-working-directory", workdir, "-config", "./config/config_validator.toml", + # Plain log lines (no ANSI color codes): the logs stay grep-able + # and trivially parseable (see logstats.py). Seednode/proxy do + # not define this flag, so it is only passed to the node binary. + "--disable-ansi-color", ] if snapshotless: argv += ["--operation-mode", "snapshotless-observer"] @@ -150,6 +155,35 @@ def slot_by_index(cfg: config.TestnetConfig) -> Dict[int, Tuple[str, int]]: return {index: (kind, shard) for index, kind, shard in cfg.validator_slots()} +def setup_launcher_log(cfg: config.TestnetConfig) -> None: + """Attach a file handler writing to ``/launcher.log``.""" + os.makedirs(cfg.log_dir, exist_ok=True) + file_handler = logging.FileHandler( + os.path.join(cfg.log_dir, "launcher.log"), encoding="utf-8") + file_handler.setFormatter(logging.Formatter( + "%(asctime)s %(levelname)-5s [%(name)s] %(message)s")) + logging.getLogger().addHandler(file_handler) + + +def service_ports(cfg: config.TestnetConfig, name: str) -> List[int]: + """Return the sweep ports for a single process name. + + Validators listen on two TCP ports (p2p + REST); both are swept + so a stale process is reaped even if one port was rebound. Every + other service listens on exactly one port. + """ + if name == "txgen": + return [cfg.txgen_port] + if name == "proxy": + return [cfg.proxy_port] + if name == "seednode": + return [cfg.seednode_port] + index = proc.validator_index_from_name(name) + if index is not None: + return [cfg.validator_p2p_port(index), cfg.validator_rest_port(index)] + raise proc.DaemonError("unknown process: %r" % name) + + def validator_names(cfg: config.TestnetConfig) -> List[str]: """Restartable validator names: cfg slots plus pidfile extras.""" cfg_indices = {index for index, _kind, _shard in cfg.validator_slots()} diff --git a/src/start.py b/src/start.py index 3672d82..c8844ca 100755 --- a/src/start.py +++ b/src/start.py @@ -69,30 +69,6 @@ def parse_args(argv: Optional[List[str]] = None) -> argparse.Namespace: return parser.parse_args(argv) -def _copy(src: str, dst: str) -> None: - # Backward-compat alias (new code uses files.copy directly). - files.copy(src, dst) - - -def _copy_glob(pattern: str, dst_dir: str) -> None: - # Backward-compat alias (new code uses files.copy_glob directly). - files.copy_glob(pattern, dst_dir) - - -def _read(path: str) -> str: - # Backward-compat alias (new code uses files.read directly). - return files.read(path) - - -def _write(path: str, text: str) -> None: - # Backward-compat alias (new code uses files.write directly). - files.write(path, text) - - -def _edit(path: str, text: str) -> None: - files.edit(path, text) - - def assert_sources_present(cfg: config.TestnetConfig) -> None: """Fail fast when a required repo checkout is missing. @@ -399,13 +375,7 @@ def main(argv: Optional[List[str]] = None) -> int: print(config.format_print_config(cfg)) return 0 - os.makedirs(cfg.log_dir, exist_ok=True) - file_handler = logging.FileHandler( - os.path.join(cfg.log_dir, "launcher.log"), encoding="utf-8") - file_handler.setFormatter(logging.Formatter( - "%(asctime)s %(levelname)-5s [%(name)s] %(message)s")) - root = logging.getLogger() - root.addHandler(file_handler) + services.setup_launcher_log(cfg) for signum in (signal.SIGINT, signal.SIGTERM): signal.signal(signum, _on_signal) diff --git a/src/status.py b/src/status.py index 75a9a83..9b0b735 100755 --- a/src/status.py +++ b/src/status.py @@ -14,9 +14,21 @@ import config import proc +import services LOG = logging.getLogger("status") +# Metric keys read from a validator's /node/status response +# (``{"data": {"metrics": {...}}}``); looked up defensively so a node +# version that renames one key degrades to "-" instead of crashing. +_METRIC_KEYS = ( + ("round", ("erd_current_round",)), + ("nonce", ("erd_nonce",)), + ("epoch", ("erd_epoch_number",)), +) + +PROBE_TIMEOUT = 2.0 + def parse_args(argv: Optional[List[str]] = None) -> argparse.Namespace: parser = argparse.ArgumentParser(description="Show testnet process status.") @@ -54,6 +66,155 @@ def collect_status(cfg: config.TestnetConfig) -> List[Tuple[str, bool, Optional[ return rows +def describe_process(cfg: config.TestnetConfig, name: str, + live_shard=None) -> str: + """Static one-line detail for a process (no network I/O). + + Validators show their role (meta / shard N / extra when the pidfile + has no slot in this topology, e.g. after downsizing) plus p2p and + REST ports; proxy shows its listen address; seednode/txgen show no + extra detail (just RUNNING/STOPPED). + ``live_shard`` (from the node's own /node/status, when reachable) + wins over the flag-derived slot, so labels stay right even when + status runs with different flags than start. + """ + index = proc.validator_index_from_name(name) + if index is not None: + if live_shard is None: + kind, shard = services.slot_by_index(cfg).get(index, ("extra", -1)) + elif live_shard == cfg.metashard_id: + kind, shard = "meta", live_shard + else: + kind, shard = "shard", live_shard + if kind == "meta": + role = "meta" + elif kind == "shard": + role = "shard %d" % shard + else: + role = "extra" + return "%s, p2p %d, rest localhost:%d" % ( + role, cfg.validator_p2p_port(index), + cfg.validator_rest_port(index)) + if name == "proxy": + return "http://127.0.0.1:%d" % cfg.proxy_port + return "" + + +def probe_http_json(url: str, timeout: float = PROBE_TIMEOUT): + """GET ``url`` and parse the JSON body. + + Return ``(True, payload)`` on HTTP 2xx, ``(False, error)`` otherwise + (connection refused, timeout, non-2xx, bad JSON). Never raises. + """ + import json + import urllib.request + + try: + with urllib.request.urlopen(url, timeout=timeout) as resp: + if not 200 <= resp.status < 300: + return False, "http %d" % resp.status + return True, json.load(resp) + except Exception as exc: # failure IS the signal here + return False, str(exc) or type(exc).__name__ + + +def _extract_metrics(payload: object) -> dict: + """Walk the ``{"data": {"metrics": {...}}}`` envelope, return metrics dict.""" + if isinstance(payload, dict): + data = payload.get("data") + if isinstance(data, dict): + inner = data.get("metrics") + if isinstance(inner, dict): + return inner + return {} + + +def node_liveness(payload: object) -> str: + """Render ``round=.. nonce=.. epoch=..`` from a /node/status payload.""" + metrics = _extract_metrics(payload) + parts = [] + for label, keys in _METRIC_KEYS: + value = "-" + for key in keys: + if metrics.get(key) is not None: + value = metrics[key] + break + parts.append("%s=%s" % (label, value)) + return " ".join(parts) + + +def node_shard_id(payload: object): + """Shard id the node reports about itself (``erd_shard_id``), or None.""" + metrics = _extract_metrics(payload) + value = metrics.get("erd_shard_id") + if isinstance(value, bool): + return None + if isinstance(value, int): + return value + if isinstance(value, str) and value.lstrip("-").isdigit(): + return int(value) + return None + + +def probe_process(cfg: config.TestnetConfig, name: str, running: bool, + timeout: float = PROBE_TIMEOUT): + """Live probe of one process; return ``(detail, live_shard)``. + + ``detail`` is the display string ("" when not running); ``live_shard`` + is the validator's self-reported shard id (None when unknown or not + a validator). A process can be RUNNING yet unreachable (still + booting, wedged) — that is exactly what this surfaces. + """ + if not running: + return "", None + index = proc.validator_index_from_name(name) + if index is not None: + # 127.0.0.1 (not "localhost"): same endpoint, but immune to + # slow/broken local DNS when resolving the name. + ok, payload = probe_http_json( + "http://127.0.0.1:%d/node/status" % cfg.validator_rest_port(index), + timeout=timeout, + ) + if ok: + return node_liveness(payload), node_shard_id(payload) + return "api DOWN (%s)" % payload, None + if name == "proxy": + ok, payload = probe_http_json( + "http://127.0.0.1:%d/network/config" % cfg.proxy_port, + timeout=timeout, + ) + return ("", None) if ok else ("api DOWN (%s)" % payload, None) + return "", None + + +def probe_all(cfg: config.TestnetConfig, rows, timeout: float = PROBE_TIMEOUT): + """Probe every row concurrently; return ``{name: probe detail}``. + + Probes are independent HTTP/TCP round-trips, so they run in a thread + pool: worst case is ~one timeout, not one timeout per process. + Never raises — an unexpected probe failure becomes a detail string. + """ + import concurrent.futures + + probes = {} + if not rows: + return probes + with concurrent.futures.ThreadPoolExecutor( + max_workers=min(len(rows), 32) + ) as pool: + future_of = { + pool.submit(probe_process, cfg, name, running, timeout): name + for name, running, _pid in rows + } + for future in concurrent.futures.as_completed(future_of): + name = future_of[future] + try: + probes[name] = future.result() + except Exception as exc: # must not break the report + probes[name] = ("probe ERROR (%s)" % (exc or type(exc).__name__), None) + return probes + + def main(argv: Optional[List[str]] = None) -> int: args = parse_args(argv) try: @@ -71,11 +232,19 @@ def main(argv: Optional[List[str]] = None) -> int: print("no pidfiles found — testnet is not running.") return 1 all_up = True + probes = probe_all(cfg, rows) for name, running, pid in rows: state = "RUNNING (pid %d)" % pid if running else "STOPPED" if not running: all_up = False - print(" %-12s %s" % (name, state)) + probe, live_shard = probes.get(name, ("", None)) + line = " %-12s %-17s %s" % ( + name, state, describe_process(cfg, name, live_shard=live_shard)) + if probe: + line += " %s" % probe + if "DOWN" in probe or "ERROR" in probe: + all_up = False + print(line.rstrip()) return 0 if all_up else 1 diff --git a/src/stop.py b/src/stop.py index 820ac3f..4cecb07 100755 --- a/src/stop.py +++ b/src/stop.py @@ -17,6 +17,7 @@ import config import proc +import services LOG = logging.getLogger("stop") @@ -36,22 +37,8 @@ def parse_args(argv: Optional[List[str]] = None) -> argparse.Namespace: def service_ports(cfg: config.TestnetConfig, name: str) -> List[int]: - """Return the sweep ports for a single process name. - - Validators listen on two TCP ports (p2p + REST); both are swept - so a stale process is reaped even if one port was rebound. Every - other service listens on exactly one port. - """ - if name == "txgen": - return [cfg.txgen_port] - if name == "proxy": - return [cfg.proxy_port] - if name == "seednode": - return [cfg.seednode_port] - index = proc.validator_index_from_name(name) - if index is not None: - return [cfg.validator_p2p_port(index), cfg.validator_rest_port(index)] - raise proc.DaemonError("unknown process: %r" % name) + """Return the sweep ports for a single process name.""" + return services.service_ports(cfg, name) def service_port(cfg: config.TestnetConfig, name: str) -> int: @@ -107,19 +94,8 @@ def stop_all(cfg: config.TestnetConfig) -> None: name = pidfile[: -len(".pid")] path = os.path.join(cfg.pid_dir, pidfile) proc.kill_by_pidfile(name, path) - # Sweep the port(s) too: pidfile names encode them. - # kill_by_port is LISTEN-only, so peers connected to a - # validator are never touched — only the listener dies. - index = proc.validator_index_from_name(name) - if index is not None: - proc.kill_by_port(cfg.validator_p2p_port(index)) - proc.kill_by_port(cfg.validator_rest_port(index)) - elif name == "seednode": - proc.kill_by_port(cfg.seednode_port) - elif name == "proxy": - proc.kill_by_port(cfg.proxy_port) - elif name == "txgen": - proc.kill_by_port(cfg.txgen_port) + for port in service_ports(cfg, name): + proc.kill_by_port(port) # Fallback sweep over every known port (covers custom topologies whose # pidfiles are already gone). diff --git a/src/txgen.py b/src/txgen.py index e15379c..55207d6 100644 --- a/src/txgen.py +++ b/src/txgen.py @@ -65,26 +65,6 @@ def parse_args(argv: Optional[List[str]] = None) -> argparse.Namespace: return parser.parse_args(argv) -def _read(path: str) -> str: - # Backward-compat alias (new code uses files.read directly). - return files.read(path) - - -def _write(path: str, text: str) -> None: - # Backward-compat alias (new code uses files.write directly). - files.write(path, text) - - -def _copy(src: str, dst: str) -> None: - # Backward-compat alias (new code uses files.copy directly). - files.copy(src, dst) - - -def _copy_glob(pattern: str, dst_dir: str) -> None: - # Backward-compat alias (new code uses files.copy_glob directly). - files.copy_glob(pattern, dst_dir) - - def _assert_proxy_up(cfg: config.TestnetConfig) -> None: """Fail fast when the testnet proxy is not running. @@ -249,12 +229,7 @@ def main(argv: Optional[List[str]] = None) -> int: print(config.format_print_config(cfg)) return 0 - os.makedirs(cfg.log_dir, exist_ok=True) - file_handler = logging.FileHandler( - os.path.join(cfg.log_dir, "launcher.log"), encoding="utf-8") - file_handler.setFormatter(logging.Formatter( - "%(asctime)s %(levelname)-5s [%(name)s] %(message)s")) - logging.getLogger().addHandler(file_handler) + services.setup_launcher_log(cfg) try: for directory in ( diff --git a/tests/test_logstats.py b/tests/test_logstats.py new file mode 100644 index 0000000..cf75a2b --- /dev/null +++ b/tests/test_logstats.py @@ -0,0 +1,225 @@ +#!/usr/bin/env python3 +"""Tests for logstats.py: per-file log level counting.""" + +import io +import os +import sys +import tempfile +import unittest +from unittest import mock + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src")) + +import logstats + + +def _cfg(tmp): + import config as config_mod + return config_mod.load_config( + {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + + +SAMPLE = """\ +ERROR [2025-04-29 07:46:37.102] [transactions] [0/4/805/(END_ROUND)] something broke +WARN [2025-04-29 07:46:38.102] [process] [metachain/13/2648/(START_ROUND)] slow round +INFO [2025-04-29 07:46:39.102] [node] [/0/0/] started +a line mentioning ERROR inside the message is OTHER, not an error +""" + + +class CountLevelsTest(unittest.TestCase): + def test_counts_levels_and_other(self): + with tempfile.TemporaryDirectory() as tmp: + path = os.path.join(tmp, "validator0.log") + with open(path, "w", encoding="utf-8") as handle: + handle.write(SAMPLE) + counts = logstats.count_levels(path) + self.assertEqual(counts["ERROR"], 1) + self.assertEqual(counts["WARN"], 1) + self.assertEqual(counts["INFO"], 1) + self.assertEqual(counts["DEBUG"], 0) + self.assertEqual(counts["TRACE"], 0) + self.assertEqual(counts["OTHER"], 1) + + def test_counts_proxy_format(self): + # The proxy omits the space: ERROR[...] instead of ERROR [...] + body = ( + "DEBUG[2026-09-17 17:39:09.971] [main] [/0/0/] x\n" + "INFO[2026-09-17 17:39:09.971] [main] [/0/0/] y\n" + "WARN[2026-09-17 17:39:09.971] [main] [/0/0/] z\n" + "ERROR[2026-09-17 17:39:09.971] [main] [/0/0/] w\n" + "ERROR[2026-09-17 17:39:35.663] another error\n" + ) + with tempfile.TemporaryDirectory() as tmp: + path = os.path.join(tmp, "proxy.log") + with open(path, "w", encoding="utf-8") as handle: + handle.write(body) + counts = logstats.count_levels(path) + self.assertEqual( + counts, {"ERROR": 2, "WARN": 1, "INFO": 1, "DEBUG": 1, + "TRACE": 0, "OTHER": 0}) + + def test_missing_file_is_zero(self): + with self.assertLogs(level="WARNING"): + counts = logstats.count_levels("/nonexistent/validator0.log") + self.assertEqual(counts["ERROR"], 0) + self.assertEqual(counts["OTHER"], 0) + + +class CollectCountsTest(unittest.TestCase): + def test_sorted_and_node_filter(self): + with tempfile.TemporaryDirectory() as tmp: + for name in ("validator1.log", "validator0.log"): + with open(os.path.join(tmp, name), "w", + encoding="utf-8") as handle: + handle.write("INFO [t] [l] [c] hi\n") + rows = logstats.collect_counts(tmp) + self.assertEqual([n for n, _c in rows], + ["validator0.log", "validator1.log"]) + only = logstats.collect_counts(tmp, node="validator1") + self.assertEqual([n for n, _c in only], ["validator1.log"]) + missing = logstats.collect_counts(tmp, node="validator9") + self.assertEqual(missing, []) + + def test_launcher_log_excluded(self): + with tempfile.TemporaryDirectory() as tmp: + with open(os.path.join(tmp, "launcher.log"), "w", + encoding="utf-8") as handle: + handle.write("INFO [t] [l] [c] hi\n") + with open(os.path.join(tmp, "validator0.log"), "w", + encoding="utf-8") as handle: + handle.write("INFO [t] [l] [c] hi\n") + rows = logstats.collect_counts(tmp) + self.assertEqual([n for n, _c in rows], ["validator0.log"]) + + +class RenderTest(unittest.TestCase): + def test_table_has_total(self): + rows = [("a.log", {"ERROR": 2, "WARN": 1, "INFO": 0, + "DEBUG": 0, "TRACE": 0, "OTHER": 0})] + out = logstats.render(rows) + self.assertIn("ERROR", out) + self.assertIn("a.log", out) + self.assertIn("TOTAL", out) + + +class ErrorLinesTest(unittest.TestCase): + def _write(self, tmp, name, body): + path = os.path.join(tmp, name) + with open(path, "w", encoding="utf-8") as handle: + handle.write(body) + return path + + def test_collects_only_real_error_lines(self): + with tempfile.TemporaryDirectory() as tmp: + self._write(tmp, "validator0.log", + "ERROR [t] [l] [c] boom\n" + "a line mentioning ERROR inside is skipped\n" + "INFO [t] [l] [c] fine\n") + self._write(tmp, "proxy.log", "INFO [t] [l] [c] fine\n") + rows = logstats.collect_error_lines(tmp) + self.assertEqual(len(rows), 1) + name, lines, hidden = rows[0] + self.assertEqual(name, "validator0.log") + self.assertEqual(len(lines), 1) + self.assertIn("boom", lines[0]) + self.assertEqual(hidden, 0) + + def test_caps_per_file_and_reports_hidden(self): + with tempfile.TemporaryDirectory() as tmp: + self._write(tmp, "validator0.log", + "".join("ERROR [t] [l] [c] e%d\n" % i + for i in range(5))) + rows = logstats.collect_error_lines(tmp, max_per_file=2) + _name, lines, hidden = rows[0] + self.assertEqual(len(lines), 2) + self.assertEqual(hidden, 3) + out = logstats.render_errors(rows) + self.assertIn("and 3 more ERROR lines", out) + + def test_trims_overlong_lines(self): + with tempfile.TemporaryDirectory() as tmp: + self._write(tmp, "validator0.log", + "ERROR [t] [l] [c] " + "x" * 600 + "\n") + rows = logstats.collect_error_lines(tmp) + _name, lines, _hidden = rows[0] + self.assertTrue(lines[0].endswith("...")) + self.assertLessEqual(len(lines[0]), + logstats.MAX_ERROR_LINE_LEN + 3) + + def test_collects_warn_lines(self): + with tempfile.TemporaryDirectory() as tmp: + self._write(tmp, "validator0.log", + "WARN [t] [l] [c] slow round\n" + "ERROR [t] [l] [c] boom\n" + "INFO [t] [l] [c] fine\n") + rows = logstats.collect_level_lines(tmp, level="WARN") + self.assertEqual(len(rows), 1) + _name, lines, hidden = rows[0] + self.assertEqual(len(lines), 1) + self.assertIn("slow round", lines[0]) + self.assertEqual(hidden, 0) + out = logstats.render_errors(rows, level="WARN") + self.assertIn("WARN lines:", out) + self.assertNotIn("ERROR lines:", out) + + +class MainTest(unittest.TestCase): + def test_no_logs_exits_1(self): + with tempfile.TemporaryDirectory() as tmp: + with mock.patch("sys.stdout", new_callable=io.StringIO): + rc = logstats.main(["--testnet-dir", tmp]) + self.assertEqual(1, rc) + + def test_reports_counts(self): + with tempfile.TemporaryDirectory() as tmp: + cfg = _cfg(tmp) + os.makedirs(cfg.log_dir, exist_ok=True) + with open(os.path.join(cfg.log_dir, "proxy.log"), "w", + encoding="utf-8") as handle: + handle.write(SAMPLE) + with mock.patch("sys.stdout", + new_callable=io.StringIO) as out: + rc = logstats.main(["--testnet-dir", tmp]) + self.assertEqual(0, rc) + self.assertIn("proxy.log", out.getvalue()) + self.assertIn("ERROR", out.getvalue()) + + def test_main_prints_error_lines(self): + with tempfile.TemporaryDirectory() as tmp: + cfg = _cfg(tmp) + os.makedirs(cfg.log_dir, exist_ok=True) + with open(os.path.join(cfg.log_dir, "validator0.log"), "w", + encoding="utf-8") as handle: + handle.write(SAMPLE) + with mock.patch("sys.stdout", + new_callable=io.StringIO) as out: + rc = logstats.main(["--testnet-dir", tmp]) + self.assertEqual(0, rc) + body = out.getvalue() + self.assertIn("ERROR lines:", body) + self.assertIn("something broke", body) + self.assertIn("=== validator0.log ===", body) + # SAMPLE has a WARN line too, shown in its own section. + self.assertIn("WARN lines:", body) + self.assertIn("slow round", body) + + def test_main_max_errors_zero_hides_lines(self): + with tempfile.TemporaryDirectory() as tmp: + cfg = _cfg(tmp) + os.makedirs(cfg.log_dir, exist_ok=True) + with open(os.path.join(cfg.log_dir, "validator0.log"), "w", + encoding="utf-8") as handle: + handle.write(SAMPLE) + with mock.patch("sys.stdout", + new_callable=io.StringIO) as out: + rc = logstats.main(["--testnet-dir", tmp, + "--max-errors", "0", + "--max-warns", "0"]) + self.assertEqual(0, rc) + self.assertNotIn("something broke", out.getvalue()) + self.assertNotIn("slow round", out.getvalue()) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_proc.py b/tests/test_proc.py index d664b44..b9a0c4f 100644 --- a/tests/test_proc.py +++ b/tests/test_proc.py @@ -13,6 +13,31 @@ import proc +class _FastHTTPServer: + """ThreadingHTTPServer that skips getfqdn() reverse-DNS on bind. + + http.server resolves the bind address via getfqdn(), which stalls for + tens of seconds on machines with broken DNS. Tests only need IP:port. + """ + + pass + + +def _make_fast_http_server(handler_class): + """Return a ThreadingHTTPServer subclass using *handler_class*.""" + from http.server import ThreadingHTTPServer + import socketserver + + class FastHTTPServer(ThreadingHTTPServer): + def server_bind(self): + socketserver.TCPServer.server_bind(self) + host, port = self.socket.getsockname()[:2] + self.server_name = host + self.server_port = port + + return FastHTTPServer + + class NameTest(unittest.TestCase): def test_validator_index(self): self.assertEqual(proc.validator_index_from_name("validator0"), 0) @@ -232,6 +257,229 @@ def test_pidfile_driven_listing(self): self.assertFalse(states["proxy"]) +class StatusDetailsTest(unittest.TestCase): + def _cfg(self, tmp): + import config as config_mod + return config_mod.load_config( + {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + + def test_describe_validator_roles_and_ports(self): + import status as status_mod + + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + # Default topology from variables.sh is 2 shards; metachain + # validators take the first indices (see validator_slots). + meta = status_mod.describe_process(cfg, "validator0") + self.assertIn("meta", meta) + self.assertIn(str(cfg.validator_p2p_port(0)), meta) + self.assertIn(str(cfg.validator_rest_port(0)), meta) + shard = status_mod.describe_process( + cfg, "validator%d" % cfg.meta_validator_count) + self.assertIn("shard 0", shard) + extra = status_mod.describe_process(cfg, "validator9999") + self.assertIn("extra", extra) + + def test_describe_services(self): + import status as status_mod + + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + self.assertEqual("", status_mod.describe_process(cfg, "seednode")) + self.assertEqual("", status_mod.describe_process(cfg, "txgen")) + self.assertIn(str(cfg.proxy_port), + status_mod.describe_process(cfg, "proxy")) + self.assertEqual("", status_mod.describe_process(cfg, "nope")) + + def test_node_liveness_missing_keys(self): + import status as status_mod + + self.assertEqual( + "round=- nonce=- epoch=-", status_mod.node_liveness({})) + self.assertEqual( + "round=120 nonce=42 epoch=3", + status_mod.node_liveness({"data": {"metrics": { + "erd_nonce": 42, + "erd_current_round": 120, + "erd_epoch_number": 3, + }}})) + + def test_node_shard_id(self): + import status as status_mod + + metrics = lambda shard: {"data": {"metrics": {"erd_shard_id": shard}}} + self.assertEqual(2, status_mod.node_shard_id(metrics(2))) + self.assertEqual(4294967295, + status_mod.node_shard_id(metrics(4294967295))) + self.assertEqual(1, status_mod.node_shard_id(metrics("1"))) + self.assertIsNone(status_mod.node_shard_id({})) + self.assertIsNone(status_mod.node_shard_id(metrics(True))) + self.assertIsNone(status_mod.node_shard_id(metrics("shard-2"))) + + def test_describe_prefers_live_shard(self): + import status as status_mod + + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + # validator9999 has no slot in any topology... + self.assertIn("extra", + status_mod.describe_process(cfg, "validator9999")) + # ...but the node's own report wins when reachable. + self.assertIn( + "shard 2", + status_mod.describe_process(cfg, "validator9999", + live_shard=2)) + self.assertIn( + "meta", + status_mod.describe_process( + cfg, "validator9999", + live_shard=cfg.metashard_id)) + + def test_probe_stopped_is_empty(self): + import dataclasses + import status as status_mod + + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + cfg = dataclasses.replace(cfg, proxy_port=47951) + self.assertEqual( + ("", None), status_mod.probe_process(cfg, "proxy", False)) + + def test_probe_down_reports_down(self): + import dataclasses + import socket + import status as status_mod + + probe = socket.socket() + probe.bind(("127.0.0.1", 0)) + closed = probe.getsockname()[1] + probe.close() + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + cfg = dataclasses.replace(cfg, proxy_port=closed) + detail, live_shard = status_mod.probe_process( + cfg, "proxy", True, timeout=1.0) + self.assertIn("api DOWN", detail) + self.assertIsNone(live_shard) + + def test_probe_validator_reports_nonce(self): + import dataclasses + import json + import threading + from http.server import BaseHTTPRequestHandler + import status as status_mod + + payload = {"data": {"metrics": { + "erd_nonce": 7, + "erd_current_round": 50, + "erd_epoch_number": 1, + "erd_shard_id": 2, + }}} + + class Handler(BaseHTTPRequestHandler): + def do_GET(self): # noqa: N802 (stdlib handler naming) + body = json.dumps(payload).encode("utf-8") + self.send_response(200) + self.send_header("Content-Type", "application/json") + self.send_header("Content-Length", str(len(body))) + self.end_headers() + self.wfile.write(body) + + def log_message(self, *args): + pass + + FastHTTPServer = _make_fast_http_server(Handler) + server = FastHTTPServer(("127.0.0.1", 0), Handler) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + try: + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + cfg = dataclasses.replace( + cfg, + validator_rest_origin=server.server_address[1], + ) + result = status_mod.probe_process( + cfg, "validator0", True, timeout=2.0) + detail, live_shard = result + self.assertNotIn("api UP", detail) + self.assertIn("nonce=7", detail) + self.assertIn("round=50", detail) + self.assertIn("epoch=1", detail) + self.assertEqual(2, live_shard) + finally: + server.shutdown() + thread.join() + + def test_probe_all_probes_concurrently(self): + import dataclasses + import json + import threading + from http.server import BaseHTTPRequestHandler + import status as status_mod + + class Handler(BaseHTTPRequestHandler): + def do_GET(self): # noqa: N802 (stdlib handler naming) + body = json.dumps({"data": {"metrics": { + "erd_nonce": 9, + "erd_current_round": 51, + "erd_epoch_number": 2, + "erd_shard_id": 1, + }}}).encode("utf-8") + self.send_response(200) + self.send_header("Content-Type", "application/json") + self.send_header("Content-Length", str(len(body))) + self.end_headers() + self.wfile.write(body) + + def log_message(self, *args): + pass + + FastHTTPServer = _make_fast_http_server(Handler) + server = FastHTTPServer(("127.0.0.1", 0), Handler) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + try: + with tempfile.TemporaryDirectory() as tmp: + cfg = self._cfg(tmp) + cfg = dataclasses.replace( + cfg, + validator_rest_origin=server.server_address[1], + ) + rows = [("validator0", True, 1234), ("proxy", False, None)] + probes = status_mod.probe_all(cfg, rows, timeout=2.0) + detail, live_shard = probes["validator0"] + self.assertIn("round=51 nonce=9 epoch=2", detail) + self.assertEqual(1, live_shard) + self.assertEqual(("", None), probes["proxy"]) + self.assertEqual({}, status_mod.probe_all(cfg, [])) + finally: + server.shutdown() + thread.join() + + def test_main_labels_from_live_shard(self): + # End-to-end through main(): validator9 is "extra" by default + # flags, but the probe reports shard 2, so that is displayed. + from unittest import mock + import io + import status as status_mod + + with tempfile.TemporaryDirectory() as tmp: + os.makedirs(os.path.join(tmp, "pids")) + with open(os.path.join(tmp, "pids", "validator9.pid"), + "w") as handle: + handle.write("%d\n" % os.getpid()) + canned = {"validator9": ("round=5 nonce=9 epoch=0", 2)} + with mock.patch.object(status_mod, "probe_all", + return_value=canned): + with mock.patch("sys.stdout", + new_callable=io.StringIO) as out: + rc = status_mod.main(["--testnet-dir", tmp]) + self.assertEqual(0, rc) + self.assertIn("shard 2", out.getvalue()) + self.assertNotIn("extra", out.getvalue()) + + class StopOneTest(unittest.TestCase): def test_stop_txgen_kills_daemon_and_pidfile(self): import dataclasses diff --git a/tests/test_restart.py b/tests/test_restart.py index b5ff9aa..6115f03 100644 --- a/tests/test_restart.py +++ b/tests/test_restart.py @@ -10,6 +10,12 @@ import restart +def _cfg(tmp): + import config as config_mod + return config_mod.load_config( + {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + + class SnapshotlessFlagTest(unittest.TestCase): def test_flag_defaults_off(self): self.assertFalse(restart.parse_args([]).snapshotless) @@ -23,25 +29,22 @@ def test_flag_parses(self): class SnapshotlessArgvTest(unittest.TestCase): def test_node_argv_without_flag(self): sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src")) - import config as config_mod import start as start_mod import tempfile with tempfile.TemporaryDirectory() as tmp: - cfg = config_mod.load_config( - {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + cfg = _cfg(tmp) argv = start_mod._node_argv(cfg, 21500, 9500, 0, tmp) self.assertNotIn("--operation-mode", argv) + self.assertIn("--disable-ansi-color", argv) def test_node_argv_with_snapshotless(self): sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src")) - import config as config_mod import start as start_mod import tempfile with tempfile.TemporaryDirectory() as tmp: - cfg = config_mod.load_config( - {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + cfg = _cfg(tmp) argv = start_mod._node_argv( cfg, 21500, 9500, 0, tmp, snapshotless=True) self.assertIn("--operation-mode", argv) @@ -49,13 +52,11 @@ def test_node_argv_with_snapshotless(self): def test_snapshotless_rejected_for_non_validators(self): sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src")) - import config as config_mod import proc import tempfile with tempfile.TemporaryDirectory() as tmp: - cfg = config_mod.load_config( - {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + cfg = _cfg(tmp) with self.assertRaises(proc.DaemonError): restart._start_one(cfg, "proxy", snapshotless=True) @@ -63,12 +64,10 @@ def test_restart_passes_flag_to_launcher(self): from unittest import mock sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src")) - import config as config_mod import tempfile with tempfile.TemporaryDirectory() as tmp: - cfg = config_mod.load_config( - {"testnet_dir": tmp}, env={"TESTNETDIR": tmp}) + cfg = _cfg(tmp) with mock.patch("stop.stop_one"), \ mock.patch.object(restart, "_wait_for_exit"), \ mock.patch("proc.read_pidfile", return_value=99999), \