From 7f37d198e4411ed07ccb349ea6ee1eeeecd53478 Mon Sep 17 00:00:00 2001 From: devRaGonSa Date: Thu, 18 Jun 2026 09:23:21 +0200 Subject: [PATCH] Add current match AdminLog freshness worker --- ...current-match-adminlog-freshness-worker.md | 115 ++++++++ backend/app/config.py | 29 ++ backend/app/rcon_admin_log_ingestion.py | 53 ++-- backend/app/rcon_current_match_worker.py | 256 ++++++++++++++++++ .../tests/test_rcon_current_match_worker.py | 193 +++++++++++++ docs/current-match-adminlog-freshness.md | 160 +++++++++++ 6 files changed, 788 insertions(+), 18 deletions(-) create mode 100644 ai/tasks/done/TASK-269-implement-current-match-adminlog-freshness-worker.md create mode 100644 backend/app/rcon_current_match_worker.py create mode 100644 backend/tests/test_rcon_current_match_worker.py create mode 100644 docs/current-match-adminlog-freshness.md diff --git a/ai/tasks/done/TASK-269-implement-current-match-adminlog-freshness-worker.md b/ai/tasks/done/TASK-269-implement-current-match-adminlog-freshness-worker.md new file mode 100644 index 0000000..4b9ce2e --- /dev/null +++ b/ai/tasks/done/TASK-269-implement-current-match-adminlog-freshness-worker.md @@ -0,0 +1,115 @@ +--- +id: TASK-269 +title: Implement current match AdminLog freshness worker +status: done +type: backend +team: Backend Senior +supporting_teams: ["Arquitecto Python"] +roadmap_item: current-match +priority: high +--- + +# TASK-269 - Implement current match AdminLog freshness worker + +## Goal + +Add an explicit lightweight worker path that keeps current-match AdminLog data fresh for the public current-match page without changing the heavy historical worker cadence globally. + +## Context + +TASK-268 confirmed that `/api/current-match/kills` and `/api/current-match/players` do not read live RCON directly. They read persisted `rcon_admin_log_events`, and those rows are refreshed by the historical AdminLog worker path. The checked-in default worker configuration still points to a `600` second historical interval with a `10` minute AdminLog lookback, which explains observed public lag growing from roughly `333s` to `651s` while CRCON live already showed newer kills. + +The fix for this task must remain operationally conservative: + +- do not change RCON hosts, ports, passwords or trusted target definitions +- do not reduce the heavy historical worker interval globally without separate approval +- do not change frontend polling unless backend freshness proves insufficient +- do not reintroduce server `#03` + +## Steps + +1. Review the existing historical AdminLog ingestion and persistence path. +2. Implement a dedicated lightweight current-match AdminLog worker or runner using the same storage path. +3. Keep the worker opt-in and deployment-disabled by default. +4. Add focused tests for trusted target selection, failure isolation, persistence reuse and config defaults. +5. Document deployment and validation without changing production deployment automatically. + +## Files to Read First + +- `AGENTS.md` +- `ai/architecture-index.md` +- `ai/repo-context.md` +- `ai/orchestrator/backend-senior.md` +- `backend/app/rcon_historical_worker.py` +- `backend/app/rcon_admin_log_ingestion.py` +- `backend/app/rcon_admin_log_storage.py` +- `backend/app/config.py` +- `backend/app/rcon_client.py` +- `backend/app/postgres_rcon_storage.py` +- `docker-compose.yml` + +## Expected Files to Modify + +- `ai/tasks/in-progress/TASK-269-implement-current-match-adminlog-freshness-worker.md` +- `backend/app/config.py` +- `backend/app/rcon_admin_log_ingestion.py` +- `backend/app/rcon_current_match_worker.py` +- `backend/tests/test_rcon_current_match_worker.py` +- `docs/current-match-adminlog-freshness.md` + +## Constraints + +- Do not run `ai-platform run`. +- Do not commit or push. +- Do not touch physical assets or `frontend/assets/img/`. +- Do not touch maps, weapons, clans or brands. +- Do not change RCON hosts, RCON ports, `27001` or other server configuration without explicit approval. +- Do not reduce the default historical worker interval globally in this task. +- Do not reactivate Elo/MMR. +- Do not reintroduce `comunidad-hispana-03`. +- Do not touch `ai/system-metrics.md`. +- Do not include `tmp/`, TASK-204 or unrelated pending changes. +- Do not use `git add .`. + +## Validation + +Before completing the task ensure: + +- `python -m compileall backend/app` +- `cd backend; python -m unittest tests.test_current_match_payload` +- `cd backend; python -m unittest tests.test_rcon_current_match_worker` +- `git diff --name-only` matches the expected scope +- documentation reflects that deployment remains opt-in + +## Outcome + +Implemented a dedicated lightweight worker entry point in `backend/app/rcon_current_match_worker.py`. + +Final scope delivered: + +- trusted-target filtering limited to `comunidad-hispana-01` and `comunidad-hispana-02` +- reuse of the existing AdminLog fetch/parsing/persistence path +- persistence into the same `rcon_admin_log_events` table +- overlap-safe defaults using existing idempotent dedupe +- explicit opt-in activation only +- deployment documentation without Compose activation changes + +Validation completed: + +- `python -m compileall backend/app` +- `cd backend; python -m unittest tests.test_current_match_payload` +- `cd backend; python -m unittest tests.test_rcon_current_match_worker` + +Operational decisions recorded: + +- default interval: `10s` +- default lookback: `180s` +- enabled default: `false` +- `docker-compose.yml` not changed +- deployment activation documented only in docs + +## Change Budget + +- Prefer fewer than 6 modified files. +- Prefer tightly scoped backend-only changes. +- Split follow-up deployment automation into a separate task if approval is required. diff --git a/backend/app/config.py b/backend/app/config.py index e234b7a..e7b40f7 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -47,6 +47,9 @@ DEFAULT_RCON_HISTORICAL_CAPTURE_MAX_RETRIES = 2 DEFAULT_RCON_HISTORICAL_CAPTURE_RETRY_DELAY_SECONDS = 15 DEFAULT_RCON_CURRENT_MATCH_CAPTURE_INTERVAL_SECONDS = 5 DEFAULT_RCON_CURRENT_MATCH_WRITER_LOCK_TIMEOUT_SECONDS = 4.0 +DEFAULT_CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS = 10 +DEFAULT_CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS = 180 +DEFAULT_CURRENT_MATCH_ADMINLOG_ENABLED = False DEFAULT_KPM_MIN_ACTIVE_SECONDS = 60 DEFAULT_RCON_BACKFILL_CHUNK_HOURS = 6 DEFAULT_RCON_BACKFILL_SLEEP_SECONDS = 1.0 @@ -678,6 +681,32 @@ def get_rcon_current_match_writer_lock_timeout_seconds() -> float: ) +def get_current_match_adminlog_interval_seconds() -> int: + """Return the dedicated current-match AdminLog worker interval.""" + return _read_int_env( + "CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS", + str(DEFAULT_CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS), + minimum=1, + ) + + +def get_current_match_adminlog_lookback_seconds() -> int: + """Return the overlap-safe AdminLog lookback for the dedicated current-match worker.""" + return _read_int_env( + "CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS", + str(DEFAULT_CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS), + minimum=1, + ) + + +def get_current_match_adminlog_enabled() -> bool: + """Return whether a deployment should enable the dedicated current-match worker.""" + return _read_bool_env( + "CURRENT_MATCH_ADMINLOG_ENABLED", + default=DEFAULT_CURRENT_MATCH_ADMINLOG_ENABLED, + ) + + def get_kpm_min_active_seconds() -> int: """Return the minimum observed active seconds required before KPM is considered valid.""" return _read_int_env( diff --git a/backend/app/rcon_admin_log_ingestion.py b/backend/app/rcon_admin_log_ingestion.py index e5badba..f6eb104 100644 --- a/backend/app/rcon_admin_log_ingestion.py +++ b/backend/app/rcon_admin_log_ingestion.py @@ -11,7 +11,7 @@ from .rcon_admin_log_storage import ( list_rcon_admin_log_event_counts, persist_rcon_admin_log_entries, ) -from .rcon_client import HllRconConnection, build_rcon_target_key, load_rcon_targets +from .rcon_client import HllRconConnection, RconServerTarget, build_rcon_target_key, load_rcon_targets @dataclass(slots=True) @@ -37,24 +37,14 @@ def ingest_rcon_admin_logs( for target in selected_targets: stats.targets_seen += 1 - target_metadata = _serialize_target(target) + target_metadata = serialize_rcon_target(target) try: - with HllRconConnection(timeout_seconds=timeout_seconds) as connection: - connection.connect(host=target.host, port=target.port, password=target.password) - payload = connection.execute_json( - "GetAdminLog", - { - "LogBackTrackTime": minutes * 60, - "Filters": [], - }, - ) - - entries = payload.get("entries") - if not isinstance(entries, list): - entries = [] - - normalized_entries = [entry for entry in entries if isinstance(entry, dict)] + normalized_entries = fetch_recent_admin_log_entries( + target, + lookback_seconds=minutes * 60, + timeout_seconds=timeout_seconds, + ) delta = persist_rcon_admin_log_entries( target=target_metadata, entries=normalized_entries, @@ -117,7 +107,34 @@ def _select_targets(target_key: str | None) -> list[object]: return selected -def _serialize_target(target: object) -> dict[str, object]: +def fetch_recent_admin_log_entries( + target: RconServerTarget, + *, + lookback_seconds: int, + timeout_seconds: float | None = None, +) -> list[dict[str, object]]: + """Fetch recent raw AdminLog entries for one configured target.""" + if lookback_seconds <= 0: + raise ValueError("lookback_seconds must be positive.") + resolved_timeout = ( + get_rcon_request_timeout_seconds() if timeout_seconds is None else timeout_seconds + ) + with HllRconConnection(timeout_seconds=resolved_timeout) as connection: + connection.connect(host=target.host, port=target.port, password=target.password) + payload = connection.execute_json( + "GetAdminLog", + { + "LogBackTrackTime": lookback_seconds, + "Filters": [], + }, + ) + entries = payload.get("entries") + if not isinstance(entries, list): + return [] + return [entry for entry in entries if isinstance(entry, dict)] + + +def serialize_rcon_target(target: object) -> dict[str, object]: return { "target_key": build_rcon_target_key(target), "external_server_id": target.external_server_id, diff --git a/backend/app/rcon_current_match_worker.py b/backend/app/rcon_current_match_worker.py new file mode 100644 index 0000000..b798a5d --- /dev/null +++ b/backend/app/rcon_current_match_worker.py @@ -0,0 +1,256 @@ +"""Dedicated lightweight AdminLog freshness worker for current-match pages.""" + +from __future__ import annotations + +import argparse +import json +import time +from collections.abc import Callable, Iterable, Sequence +from datetime import datetime, timezone +from pathlib import Path + +from .config import ( + get_current_match_adminlog_enabled, + get_current_match_adminlog_interval_seconds, + get_current_match_adminlog_lookback_seconds, + get_rcon_current_match_writer_lock_timeout_seconds, +) +from .rcon_admin_log_ingestion import fetch_recent_admin_log_entries, serialize_rcon_target +from .rcon_admin_log_storage import persist_rcon_admin_log_entries +from .rcon_client import RconServerTarget, build_rcon_target_key, load_rcon_targets +from .scoreboard_origins import list_trusted_public_scoreboard_origins +from .writer_lock import backend_writer_lock, build_writer_lock_holder + + +def list_current_match_trusted_targets() -> list[RconServerTarget]: + """Return only the configured RCON targets trusted for public current-match pages.""" + trusted_keys = { + origin.slug for origin in list_trusted_public_scoreboard_origins() + } + return [ + target + for target in load_rcon_targets() + if build_rcon_target_key(target) in trusted_keys + ] + + +def run_current_match_adminlog_refresh_once( + *, + lookback_seconds: int | None = None, + targets: Sequence[RconServerTarget] | None = None, + fetch_entries_fn: Callable[..., list[dict[str, object]]] = fetch_recent_admin_log_entries, + persist_entries_fn: Callable[..., dict[str, int]] = persist_rcon_admin_log_entries, + db_path: object = None, +) -> dict[str, object]: + """Refresh recent AdminLog rows once for trusted current-match targets.""" + with backend_writer_lock( + holder=build_writer_lock_holder("app.rcon_current_match_worker once"), + timeout_seconds=get_rcon_current_match_writer_lock_timeout_seconds(), + ): + return run_current_match_adminlog_refresh_once_unlocked( + lookback_seconds=lookback_seconds, + targets=targets, + fetch_entries_fn=fetch_entries_fn, + persist_entries_fn=persist_entries_fn, + db_path=db_path, + ) + + +def run_current_match_adminlog_refresh_once_unlocked( + *, + lookback_seconds: int | None = None, + targets: Sequence[RconServerTarget] | None = None, + fetch_entries_fn: Callable[..., list[dict[str, object]]] = fetch_recent_admin_log_entries, + persist_entries_fn: Callable[..., dict[str, int]] = persist_rcon_admin_log_entries, + db_path: object = None, +) -> dict[str, object]: + """Refresh recent AdminLog rows once assuming the shared writer lock is already held.""" + resolved_lookback_seconds = ( + get_current_match_adminlog_lookback_seconds() + if lookback_seconds is None + else int(lookback_seconds) + ) + if resolved_lookback_seconds <= 0: + raise ValueError("lookback_seconds must be positive.") + + resolved_db_path = Path(db_path) if isinstance(db_path, str) else db_path + selected_targets = list(targets) if targets is not None else list_current_match_trusted_targets() + if not selected_targets: + raise RuntimeError("No trusted current-match RCON targets are configured.") + + timeout_seconds = None + refreshed_at = datetime.now(timezone.utc).isoformat(timespec="seconds").replace("+00:00", "Z") + items: list[dict[str, object]] = [] + errors: list[dict[str, object]] = [] + totals = { + "targets_seen": 0, + "entries_seen": 0, + "events_inserted": 0, + "duplicate_events": 0, + "failed_targets": 0, + } + + for target in selected_targets: + totals["targets_seen"] += 1 + target_metadata = serialize_rcon_target(target) + started = time.perf_counter() + try: + entries = fetch_entries_fn( + target, + lookback_seconds=resolved_lookback_seconds, + timeout_seconds=timeout_seconds, + ) + delta = persist_entries_fn( + target=target_metadata, + entries=entries, + db_path=resolved_db_path, + ) + duration_ms = round((time.perf_counter() - started) * 1000, 2) + totals["entries_seen"] += int(delta.get("events_seen") or 0) + totals["events_inserted"] += int(delta.get("events_inserted") or 0) + totals["duplicate_events"] += int(delta.get("duplicate_events") or 0) + items.append( + { + "target_key": target_metadata["target_key"], + "external_server_id": target_metadata["external_server_id"], + "name": target_metadata["name"], + "entries_seen": int(delta.get("events_seen") or 0), + "events_inserted": int(delta.get("events_inserted") or 0), + "duplicate_events": int(delta.get("duplicate_events") or 0), + "duration_ms": duration_ms, + } + ) + except Exception as exc: # noqa: BLE001 - per-target failure must not kill the loop + totals["failed_targets"] += 1 + errors.append( + { + "target_key": target_metadata["target_key"], + "external_server_id": target_metadata["external_server_id"], + "name": target_metadata["name"], + "error_type": type(exc).__name__, + "message": str(exc), + } + ) + + return { + "status": "ok" if not errors else ("partial" if items else "error"), + "worker_enabled": get_current_match_adminlog_enabled(), + "refreshed_at": refreshed_at, + "lookback_seconds": resolved_lookback_seconds, + "targets": items, + "errors": errors, + "totals": totals, + } + + +def run_current_match_adminlog_refresh_loop( + *, + interval_seconds: int | None = None, + lookback_seconds: int | None = None, + max_runs: int | None = None, +) -> None: + """Run the lightweight current-match AdminLog refresher in a loop.""" + resolved_interval_seconds = ( + get_current_match_adminlog_interval_seconds() + if interval_seconds is None + else int(interval_seconds) + ) + if resolved_interval_seconds <= 0: + raise ValueError("interval_seconds must be positive.") + if max_runs is not None and max_runs <= 0: + raise ValueError("max_runs must be positive when provided.") + + run_count = 0 + _emit_worker_event( + "current-match-adminlog-worker-started", + enabled=get_current_match_adminlog_enabled(), + interval_seconds=resolved_interval_seconds, + lookback_seconds=( + get_current_match_adminlog_lookback_seconds() + if lookback_seconds is None + else int(lookback_seconds) + ), + targets=[ + { + "target_key": build_rcon_target_key(target), + "external_server_id": target.external_server_id, + "name": target.name, + } + for target in list_current_match_trusted_targets() + ], + ) + try: + while max_runs is None or run_count < max_runs: + run_count += 1 + result = run_current_match_adminlog_refresh_once( + lookback_seconds=lookback_seconds, + ) + _emit_worker_event( + "current-match-adminlog-cycle-finished", + run=run_count, + result=result, + ) + if max_runs is not None and run_count >= max_runs: + break + time.sleep(resolved_interval_seconds) + except KeyboardInterrupt: + _emit_worker_event("current-match-adminlog-worker-stopped", reason="keyboard-interrupt") + + +def build_arg_parser() -> argparse.ArgumentParser: + parser = argparse.ArgumentParser( + description="Lightweight current-match AdminLog freshness worker.", + ) + parser.add_argument( + "mode", + choices=("once", "loop"), + help="run once or keep polling trusted current-match targets", + ) + parser.add_argument( + "--interval", + type=int, + default=get_current_match_adminlog_interval_seconds(), + help="seconds between loop iterations", + ) + parser.add_argument( + "--lookback-seconds", + type=int, + default=get_current_match_adminlog_lookback_seconds(), + help="overlap-safe AdminLog lookback window in seconds", + ) + parser.add_argument( + "--max-runs", + type=int, + help="optional safety cap for loop mode", + ) + return parser + + +def main(argv: Iterable[str] | None = None) -> int: + parser = build_arg_parser() + args = parser.parse_args(list(argv) if argv is not None else None) + if args.mode == "once": + print( + json.dumps( + run_current_match_adminlog_refresh_once( + lookback_seconds=args.lookback_seconds, + ), + indent=2, + ) + ) + return 0 + + run_current_match_adminlog_refresh_loop( + interval_seconds=args.interval, + lookback_seconds=args.lookback_seconds, + max_runs=args.max_runs, + ) + return 0 + + +def _emit_worker_event(event: str, **fields: object) -> None: + print(json.dumps({"event": event, **fields}, indent=2, default=str), flush=True) + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/backend/tests/test_rcon_current_match_worker.py b/backend/tests/test_rcon_current_match_worker.py new file mode 100644 index 0000000..289dee9 --- /dev/null +++ b/backend/tests/test_rcon_current_match_worker.py @@ -0,0 +1,193 @@ +from __future__ import annotations + +import os +import tempfile +import unittest +from contextlib import contextmanager +from types import SimpleNamespace +from unittest.mock import patch + +from app.config import ( + get_current_match_adminlog_enabled, + get_current_match_adminlog_interval_seconds, + get_current_match_adminlog_lookback_seconds, +) +from app.rcon_current_match_worker import ( + list_current_match_trusted_targets, + run_current_match_adminlog_refresh_once_unlocked, +) + + +TARGET_01 = SimpleNamespace( + external_server_id="comunidad-hispana-01", + name="Comunidad Hispana #01", + host="203.0.113.10", + port=7779, + password="secret-01", + region="ES", + game_port=None, + query_port=None, + source_name="community-hispana-rcon", +) + +TARGET_02 = SimpleNamespace( + external_server_id="comunidad-hispana-02", + name="Comunidad Hispana #02", + host="203.0.113.11", + port=7879, + password="secret-02", + region="ES", + game_port=None, + query_port=None, + source_name="community-hispana-rcon", +) + +TARGET_03 = SimpleNamespace( + external_server_id="comunidad-hispana-03", + name="Comunidad Hispana #03", + host="203.0.113.12", + port=7979, + password="secret-03", + region="ES", + game_port=None, + query_port=None, + source_name="community-hispana-rcon", +) + + +class RconCurrentMatchWorkerTests(unittest.TestCase): + def test_list_current_match_trusted_targets_filters_only_01_and_02(self) -> None: + with patch( + "app.rcon_current_match_worker.load_rcon_targets", + return_value=(TARGET_01, TARGET_02, TARGET_03), + ): + selected = list_current_match_trusted_targets() + + self.assertEqual( + [target.external_server_id for target in selected], + ["comunidad-hispana-01", "comunidad-hispana-02"], + ) + + def test_once_unlocked_calls_existing_persistence_path(self) -> None: + fetch_calls: list[object] = [] + persist_calls: list[dict[str, object]] = [] + + def fake_fetch(target, *, lookback_seconds, timeout_seconds): + fetch_calls.append((target.external_server_id, lookback_seconds, timeout_seconds)) + return [{"timestamp": "2026-06-18T18:00:00Z", "message": "[1 (1)] Killer(Allies) -> Victim(Axis) with Rifle"}] + + def fake_persist(*, target, entries, db_path=None): + persist_calls.append({"target": target, "entries": entries, "db_path": db_path}) + return { + "events_seen": len(entries), + "events_inserted": len(entries), + "duplicate_events": 0, + } + + result = run_current_match_adminlog_refresh_once_unlocked( + lookback_seconds=180, + targets=[TARGET_01], + fetch_entries_fn=fake_fetch, + persist_entries_fn=fake_persist, + ) + + self.assertEqual(fetch_calls, [("comunidad-hispana-01", 180, None)]) + self.assertEqual(len(persist_calls), 1) + self.assertEqual(persist_calls[0]["target"]["target_key"], "comunidad-hispana-01") + self.assertEqual(result["totals"]["events_inserted"], 1) + self.assertEqual(result["status"], "ok") + + def test_failing_target_does_not_block_other_target(self) -> None: + def fake_fetch(target, *, lookback_seconds, timeout_seconds): + if target.external_server_id == "comunidad-hispana-01": + raise RuntimeError("boom") + return [{"timestamp": "2026-06-18T18:00:00Z", "message": "[1 (1)] Killer(Allies) -> Victim(Axis) with Rifle"}] + + def fake_persist(*, target, entries, db_path=None): + return { + "events_seen": len(entries), + "events_inserted": len(entries), + "duplicate_events": 0, + } + + result = run_current_match_adminlog_refresh_once_unlocked( + lookback_seconds=180, + targets=[TARGET_01, TARGET_02], + fetch_entries_fn=fake_fetch, + persist_entries_fn=fake_persist, + ) + + self.assertEqual(result["status"], "partial") + self.assertEqual(result["totals"]["failed_targets"], 1) + self.assertEqual(result["totals"]["events_inserted"], 1) + self.assertEqual(len(result["targets"]), 1) + self.assertEqual(result["targets"][0]["target_key"], "comunidad-hispana-02") + + def test_overlapping_windows_remain_idempotent_via_existing_persistence(self) -> None: + entry = { + "timestamp": "2026-06-18T18:00:00Z", + "message": ( + "[5:00 min (321)] KILL: Alpha(Allies/76561198000000001) -> " + "Bravo(Axis/76561198000000002) with M1 GARAND" + ), + } + with tempfile.TemporaryDirectory() as temp_dir: + db_path = os.path.join(temp_dir, "current_match.sqlite3") + + def fake_fetch(target, *, lookback_seconds, timeout_seconds): + return [entry] + + first = run_current_match_adminlog_refresh_once_unlocked( + lookback_seconds=180, + targets=[TARGET_01], + fetch_entries_fn=fake_fetch, + db_path=db_path, + ) + second = run_current_match_adminlog_refresh_once_unlocked( + lookback_seconds=180, + targets=[TARGET_01], + fetch_entries_fn=fake_fetch, + db_path=db_path, + ) + + self.assertEqual(first["totals"]["events_inserted"], 1) + self.assertEqual(first["totals"]["duplicate_events"], 0) + self.assertEqual(second["totals"]["events_inserted"], 0) + self.assertEqual(second["totals"]["duplicate_events"], 1) + + def test_current_match_adminlog_config_defaults_and_overrides(self) -> None: + with _temporary_env( + CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS=None, + CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS=None, + CURRENT_MATCH_ADMINLOG_ENABLED=None, + ): + self.assertEqual(get_current_match_adminlog_interval_seconds(), 10) + self.assertEqual(get_current_match_adminlog_lookback_seconds(), 180) + self.assertIs(get_current_match_adminlog_enabled(), False) + + with _temporary_env( + CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS="15", + CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS="120", + CURRENT_MATCH_ADMINLOG_ENABLED="true", + ): + self.assertEqual(get_current_match_adminlog_interval_seconds(), 15) + self.assertEqual(get_current_match_adminlog_lookback_seconds(), 120) + self.assertIs(get_current_match_adminlog_enabled(), True) + + +@contextmanager +def _temporary_env(**values: str | None): + previous = {name: os.environ.get(name) for name in values} + try: + for name, value in values.items(): + if value is None: + os.environ.pop(name, None) + else: + os.environ[name] = value + yield + finally: + for name, value in previous.items(): + if value is None: + os.environ.pop(name, None) + else: + os.environ[name] = value diff --git a/docs/current-match-adminlog-freshness.md b/docs/current-match-adminlog-freshness.md new file mode 100644 index 0000000..597a226 --- /dev/null +++ b/docs/current-match-adminlog-freshness.md @@ -0,0 +1,160 @@ +# Current Match AdminLog Freshness + +## Problem + +The public current-match page was lagging because: + +- `/api/current-match/kills` reads persisted `rcon_admin_log_events` +- `/api/current-match/players` reads persisted `rcon_admin_log_events` +- those endpoints do not ingest AdminLog during the request path +- the checked-in historical worker path refreshes AdminLog on a much slower cadence +- frontend polling was already faster than backend data freshness + +Observed behavior from TASK-268 matched this design: + +- checked-in historical worker interval: `600` seconds +- checked-in AdminLog lookback: `10` minutes +- observed public lag growing from about `333s` to about `651s` + +## Solution + +Add a dedicated lightweight worker: + +- module: `python -m app.rcon_current_match_worker` +- scope: only trusted current-match servers + - `comunidad-hispana-01` + - `comunidad-hispana-02` +- fetches recent AdminLog directly from existing configured RCON targets +- reuses existing parsing and `persist_rcon_admin_log_entries(...)` +- writes into the same `rcon_admin_log_events` table +- relies on existing dedupe/idempotency for overlap-safe windows + +Default worker settings: + +- `CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS=10` +- `CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS=180` +- `CURRENT_MATCH_ADMINLOG_ENABLED=false` + +The worker is opt-in. This task does not change Compose to start it automatically. + +## Design Notes + +The worker intentionally avoids: + +- changing RCON hosts, ports or passwords +- introducing a second AdminLog schema +- reducing the heavy historical worker interval globally +- pushing ingestion into `/api/current-match/*` request handlers + +Each iteration: + +1. filters configured RCON targets down to trusted current-match servers +2. fetches recent AdminLog entries with a small overlap window +3. persists through the existing idempotent storage path +4. logs per-target counts for: + - `entries_seen` + - `events_inserted` + - `duplicate_events` + - `duration_ms` +5. continues if one server fails + +## Run Commands + +Local one-shot validation: + +```powershell +cd backend +python -m app.rcon_current_match_worker once +``` + +Local loop: + +```powershell +cd backend +python -m app.rcon_current_match_worker loop --interval 10 --lookback-seconds 180 +``` + +Docker/Compose-style ad hoc command without changing deployment defaults: + +```powershell +docker compose run --rm backend python -m app.rcon_current_match_worker loop --interval 10 --lookback-seconds 180 +``` + +Example service snippet for a future approved deployment: + +```yaml +current-match-adminlog-worker: + profiles: ["advanced"] + build: + context: ./backend + command: ["python", "-m", "app.rcon_current_match_worker", "loop"] + environment: + HLL_BACKEND_DATABASE_URL: ${HLL_BACKEND_DATABASE_URL} + HLL_BACKEND_RCON_TARGETS: ${HLL_BACKEND_RCON_TARGETS} + CURRENT_MATCH_ADMINLOG_ENABLED: ${CURRENT_MATCH_ADMINLOG_ENABLED:-false} + CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS: ${CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS:-10} + CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS: ${CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS:-180} +``` + +The snippet is documented only. It is not applied automatically by this task. + +## Post-Deployment Validation + +Watch worker logs for per-target counts and errors. The useful signals are: + +- `entries_seen` +- `events_inserted` +- `duplicate_events` +- `target_key` +- `duration_ms` + +Sample the public API every 10 seconds: + +```powershell +$killsBase = "https://comunidadhll.devzamode.es/api/current-match/kills?server=comunidad-hispana-02&limit=18" +$playersBase = "https://comunidadhll.devzamode.es/api/current-match/players?server=comunidad-hispana-02" + +1..18 | ForEach-Object { + $now = Get-Date + $ts = [DateTimeOffset]::UtcNow.ToUnixTimeMilliseconds() + + $kills = Invoke-RestMethod "$killsBase&_ts=$ts" -Headers @{ "Cache-Control" = "no-cache"; "Pragma" = "no-cache" } + $killItems = @($kills.data.items) + $topKill = $killItems | Select-Object -First 1 + + $players = Invoke-RestMethod "$playersBase&_ts=$ts" -Headers @{ "Cache-Control" = "no-cache"; "Pragma" = "no-cache" } + $playerItems = @($players.data.items) + $topPlayers = $playerItems | Sort-Object -Property kills -Descending | Select-Object -First 5 | ForEach-Object { + "$($_.player_name):K=$($_.kills):D=$($_.deaths):Team=$($_.team)" + } + + $killLocalTime = "" + $lagSeconds = "" + if ($topKill -and $topKill.server_time) { + $killDate = [DateTimeOffset]::FromUnixTimeSeconds([int64]$topKill.server_time).ToLocalTime() + $killLocalTime = $killDate.ToString("HH:mm:ss") + $lagSeconds = [int](([DateTimeOffset]::Now - $killDate).TotalSeconds) + } + + [PSCustomObject]@{ + sample = $_ + sampled_at = $now.ToString("HH:mm:ss") + kills_scope = $kills.data.scope + kills_count = $killItems.Count + first_id = if ($killItems.Count -gt 0) { $killItems[0].event_id } else { "" } + first_kill_time = $killLocalTime + estimated_lag_seconds = $lagSeconds + first_kill = if ($topKill) { "$($topKill.killer_name)->$($topKill.victim_name):$($topKill.weapon)" } else { "" } + players_count = $playerItems.Count + top_players = ($topPlayers -join " | ") + } + + Start-Sleep -Seconds 10 +} +``` + +Expected outcome after deployment: + +- new CRCON kills should appear in `/api/current-match/kills` within roughly `10-30` seconds +- `/api/current-match/players` should advance accordingly +- the frontend should reflect it without further polling changes