diff --git a/ai/tasks/done/TASK-271-split-rcon-live-ingestion-from-historical-materialization.md b/ai/tasks/done/TASK-271-split-rcon-live-ingestion-from-historical-materialization.md new file mode 100644 index 0000000..b44e670 --- /dev/null +++ b/ai/tasks/done/TASK-271-split-rcon-live-ingestion-from-historical-materialization.md @@ -0,0 +1,128 @@ +--- +id: TASK-271 +title: Split RCON live ingestion from historical materialization +status: in-progress +type: backend +team: Backend Senior +supporting_teams: ["Arquitecto Python"] +roadmap_item: current-match +priority: high +--- + +# TASK-271 - Split RCON live ingestion from historical materialization + +## Goal + +Separate near-real-time AdminLog ingestion for current-match freshness from the slow historical materialization path so `/api/current-match/kills` and `/api/current-match/players` can stay fresh without waiting on heavy historical work. + +## Context + +Production evidence shows the current combined worker design is starving the current-match read model: + +- production service `hll-vietnam-rcon-historical-worker-1` currently runs `python -m app.rcon_historical_worker loop` +- configured interval is `HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS=2` +- configured AdminLog lookback is `HLL_BACKEND_RCON_ADMIN_LOG_LOOKBACK_MINUTES=10` +- real `rcon_historical_capture_runs` durations are around `15-30` minutes +- recent runs overlapped and one failed with PostgreSQL deadlock +- each cycle materializes roughly `838k` player-stat rows and updates roughly `392-394` materialized matches +- `/api/current-match/kills` and `/api/current-match/players` read `rcon_admin_log_events`, not live CRCON/RCON per public request + +This means the current-match feed problem is not primarily frontend rendering. The source table is not being refreshed frequently enough because live AdminLog ingestion is coupled to heavy historical materialization. + +This task must preserve the current product identity and must not change frontend layout, CSS, assets, RCON hosts, ports, passwords, server list, `27001`, ranking semantics, Elo/MMR activation, or reintroduce `comunidad-hispana-03`. + +## Steps + +1. Inspect the current historical worker, current-match worker, AdminLog ingestion/storage, materialization path, API read path and Portainer deployment. +2. Implement a dedicated lightweight live AdminLog worker that only refreshes `rcon_admin_log_events`. +3. Reduce repeated PostgreSQL schema initialization in the live path by moving obvious DDL/init work out of hot loops and request reads. +4. Add no-overlap protection for heavy historical materialization so concurrent heavy runs skip cleanly instead of overlapping. +5. Update Portainer deployment so live ingestion and heavy historical materialization run as separate services with safe cadences. +6. Add or update focused tests and refresh the current-match freshness documentation with post-deploy validation commands. + +## 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_current_match_worker.py` +- `backend/app/rcon_admin_log_ingestion.py` +- `backend/app/rcon_admin_log_storage.py` +- `backend/app/postgres_rcon_storage.py` +- `backend/app/payloads.py` +- `deploy/portainer/docker-compose.nas.yml` +- `docs/current-match-adminlog-freshness.md` + +## Expected Files to Modify + +- `ai/tasks/in-progress/TASK-271-split-rcon-live-ingestion-from-historical-materialization.md` +- `backend/app/rcon_current_match_worker.py` +- `backend/app/rcon_admin_log_storage.py` +- `backend/app/postgres_rcon_storage.py` +- `backend/app/rcon_historical_storage.py` +- `backend/app/rcon_historical_worker.py` +- `backend/tests/test_rcon_current_match_worker.py` +- `backend/tests/test_rcon_historical_worker.py` +- `backend/tests/test_current_match_payload.py` +- `deploy/portainer/docker-compose.nas.yml` +- `docs/current-match-adminlog-freshness.md` + +## Constraints + +- Do not run `ai-platform run`. +- Do not commit or push. +- Do not use `git add .`. +- Do not touch `ai/system-metrics.md`. +- Do not include `tmp/`. +- Do not include TASK-204, TASK-242 or unrelated in-progress/done tasks. +- Do not touch weapon assets, map assets or clan assets. +- Do not touch frontend layout or CSS. +- Do not change RCON hosts, ports, passwords, `27001` or the configured server list. +- Do not reintroduce `comunidad-hispana-03`. +- Do not reactivate Elo/MMR. +- Do not change ranking semantics or fabricate support rankings. +- Do not change annual tops/player search behavior except where explicitly needed to stop them from blocking live ingestion. +- Keep the change backend/deployment/documentation scoped and reviewable. + +## 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_historical_worker` +- `cd backend; python -m unittest tests.test_rcon_current_match_worker` +- `git diff --name-only` matches the intended scope +- no unrelated dirty files were modified +- documentation reflects the new live worker split and post-deploy checks + +## Outcome + +Implemented scope: + +- dedicated live AdminLog worker path kept in `backend/app/rcon_current_match_worker.py` +- live worker storage initialization moved out of the hot loop body and out of per-target persistence calls +- live worker no longer waits on the shared long-running backend writer lock +- current-match persistence stays idempotent through the existing `rcon_admin_log_events` dedupe path +- historical capture/materialization path gained a single-running historical guard and returns `skipped` with `already-running` when a heavy run is still active +- Portainer deployment now splits `rcon-live-adminlog-worker` from `rcon-historical-worker` +- heavy historical cadence was set explicitly to `900` seconds in the Portainer compose file + +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_historical_worker` +- `cd backend; python -m unittest tests.test_rcon_current_match_worker` + +Follow-up intentionally left out of central scope: + +- `TEAM KILL` parser correctness remains a separate follow-up task unless handled later with a tiny isolated patch + +## Change Budget + +- Prefer fewer than 5 modified files when feasible, but accept a slightly larger backend/deploy/docs scope if required to complete the split safely. +- Prefer focused edits over broad refactors. +- Split out follow-up correctness issues instead of expanding scope unnecessarily. diff --git a/backend/app/postgres_rcon_storage.py b/backend/app/postgres_rcon_storage.py index bbea491..d129b94 100644 --- a/backend/app/postgres_rcon_storage.py +++ b/backend/app/postgres_rcon_storage.py @@ -17,6 +17,9 @@ COMPETITIVE_WINDOW_GAP_SECONDS = 1800 COMPETITIVE_MODE_PARTIAL = "partial" COMPETITIVE_MODE_APPROXIMATE = "approximate" COMPETITIVE_MODE_EXACT = "exact" +RUNNING_HISTORICAL_CAPTURE_CONFLICT_MESSAGE = ( + "historical materialization capture already running" +) RCON_SCHEMA_SQL = """ @@ -51,6 +54,10 @@ CREATE TABLE IF NOT EXISTS rcon_historical_capture_runs ( created_at TIMESTAMPTZ NOT NULL DEFAULT CURRENT_TIMESTAMP ); +CREATE UNIQUE INDEX IF NOT EXISTS idx_rcon_historical_single_running_historical +ON rcon_historical_capture_runs(mode) +WHERE status = 'running' AND mode = 'historical'; + CREATE TABLE IF NOT EXISTS rcon_historical_samples ( id BIGSERIAL PRIMARY KEY, target_id BIGINT NOT NULL REFERENCES rcon_historical_targets(id), @@ -475,14 +482,27 @@ def connect_postgres_compat(*, initialize: bool = True): def start_capture_run(*, mode: str, target_scope: str) -> int: initialize_postgres_rcon_storage() with connect_postgres() as connection: - row = connection.execute( - """ - INSERT INTO rcon_historical_capture_runs (mode, status, target_scope, started_at) - VALUES (%s, 'running', %s, %s) - RETURNING id - """, - (mode, target_scope, _utc_now_iso()), - ).fetchone() + try: + row = connection.execute( + """ + INSERT INTO rcon_historical_capture_runs (mode, status, target_scope, started_at) + VALUES (%s, 'running', %s, %s) + RETURNING id + """, + (mode, target_scope, _utc_now_iso()), + ).fetchone() + except Exception as error: + try: + import psycopg + except ImportError: + psycopg = None # type: ignore[assignment] + if ( + mode == "historical" + and psycopg is not None + and isinstance(error, psycopg.errors.UniqueViolation) + ): + raise RuntimeError(RUNNING_HISTORICAL_CAPTURE_CONFLICT_MESSAGE) from error + raise return int(row["id"]) diff --git a/backend/app/rcon_admin_log_storage.py b/backend/app/rcon_admin_log_storage.py index bd4193e..fa59cdb 100644 --- a/backend/app/rcon_admin_log_storage.py +++ b/backend/app/rcon_admin_log_storage.py @@ -108,12 +108,21 @@ def persist_rcon_admin_log_entries( target: Mapping[str, object], entries: list[dict[str, object]], db_path: Path | None = None, + ensure_storage: bool = True, ) -> dict[str, int]: """Persist raw and parsed AdminLog entries idempotently.""" if use_postgres_rcon_storage(explicit_sqlite_path=db_path): - return _persist_rcon_admin_log_entries_postgres(target=target, entries=entries) + return _persist_rcon_admin_log_entries_postgres( + target=target, + entries=entries, + ensure_storage=ensure_storage, + ) - resolved_path = initialize_rcon_admin_log_storage(db_path=db_path) + resolved_path = ( + initialize_rcon_admin_log_storage(db_path=db_path) + if ensure_storage + else (db_path or get_storage_path()) + ) target_key = str(target.get("target_key") or target.get("external_server_id") or "") if not target_key: raise ValueError("target must include target_key or external_server_id") @@ -1165,6 +1174,7 @@ def _persist_rcon_admin_log_entries_postgres( *, target: Mapping[str, object], entries: list[dict[str, object]], + ensure_storage: bool, ) -> dict[str, int]: from .postgres_rcon_storage import connect_postgres_compat @@ -1175,7 +1185,7 @@ def _persist_rcon_admin_log_entries_postgres( external_server_id = target.get("external_server_id") inserted = 0 duplicates = 0 - with connect_postgres_compat() as connection: + with connect_postgres_compat(initialize=ensure_storage) as connection: for entry in entries: parsed = parse_rcon_admin_log_entry(entry) raw_message = str(parsed.get("raw_message") or "") diff --git a/backend/app/rcon_current_match_worker.py b/backend/app/rcon_current_match_worker.py index b798a5d..7b55155 100644 --- a/backend/app/rcon_current_match_worker.py +++ b/backend/app/rcon_current_match_worker.py @@ -13,13 +13,14 @@ 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_admin_log_storage import ( + initialize_rcon_admin_log_storage, + 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]: @@ -41,19 +42,17 @@ def run_current_match_adminlog_refresh_once( 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, + ensure_storage: bool = True, ) -> 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, - ) + 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, + ensure_storage=ensure_storage, + ) def run_current_match_adminlog_refresh_once_unlocked( @@ -63,12 +62,11 @@ def run_current_match_adminlog_refresh_once_unlocked( 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, + ensure_storage: bool = True, ) -> 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) + """Refresh recent AdminLog rows once using idempotent event inserts only.""" + resolved_lookback_seconds = _resolve_lookback_seconds( + lookback_seconds=lookback_seconds, ) if resolved_lookback_seconds <= 0: raise ValueError("lookback_seconds must be positive.") @@ -78,6 +76,8 @@ def run_current_match_adminlog_refresh_once_unlocked( if not selected_targets: raise RuntimeError("No trusted current-match RCON targets are configured.") + if ensure_storage: + initialize_rcon_admin_log_storage(db_path=resolved_db_path) timeout_seconds = None refreshed_at = datetime.now(timezone.utc).isoformat(timespec="seconds").replace("+00:00", "Z") items: list[dict[str, object]] = [] @@ -104,6 +104,7 @@ def run_current_match_adminlog_refresh_once_unlocked( target=target_metadata, entries=entries, db_path=resolved_db_path, + ensure_storage=False, ) duration_ms = round((time.perf_counter() - started) * 1000, 2) totals["entries_seen"] += int(delta.get("events_seen") or 0) @@ -147,6 +148,7 @@ def run_current_match_adminlog_refresh_loop( *, interval_seconds: int | None = None, lookback_seconds: int | None = None, + lookback_minutes: int | None = None, max_runs: int | None = None, ) -> None: """Run the lightweight current-match AdminLog refresher in a loop.""" @@ -165,10 +167,9 @@ def run_current_match_adminlog_refresh_loop( "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) + lookback_seconds=_resolve_lookback_seconds( + lookback_seconds=lookback_seconds, + lookback_minutes=lookback_minutes, ), targets=[ { @@ -179,11 +180,17 @@ def run_current_match_adminlog_refresh_loop( for target in list_current_match_trusted_targets() ], ) + initialize_rcon_admin_log_storage() try: while max_runs is None or run_count < max_runs: run_count += 1 + _emit_worker_event("current-match-adminlog-cycle-started", run=run_count) result = run_current_match_adminlog_refresh_once( - lookback_seconds=lookback_seconds, + lookback_seconds=_resolve_lookback_seconds( + lookback_seconds=lookback_seconds, + lookback_minutes=lookback_minutes, + ), + ensure_storage=False, ) _emit_worker_event( "current-match-adminlog-cycle-finished", @@ -192,6 +199,11 @@ def run_current_match_adminlog_refresh_loop( ) if max_runs is not None and run_count >= max_runs: break + _emit_worker_event( + "current-match-adminlog-sleep-started", + run=run_count, + sleep_seconds=resolved_interval_seconds, + ) time.sleep(resolved_interval_seconds) except KeyboardInterrupt: _emit_worker_event("current-match-adminlog-worker-stopped", reason="keyboard-interrupt") @@ -218,6 +230,11 @@ def build_arg_parser() -> argparse.ArgumentParser: default=get_current_match_adminlog_lookback_seconds(), help="overlap-safe AdminLog lookback window in seconds", ) + parser.add_argument( + "--lookback-minutes", + type=int, + help="optional overlap-safe AdminLog lookback window in minutes", + ) parser.add_argument( "--max-runs", type=int, @@ -230,10 +247,14 @@ 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": + lookback_seconds = _resolve_lookback_seconds( + lookback_seconds=args.lookback_seconds, + lookback_minutes=args.lookback_minutes, + ) print( json.dumps( run_current_match_adminlog_refresh_once( - lookback_seconds=args.lookback_seconds, + lookback_seconds=lookback_seconds, ), indent=2, ) @@ -243,11 +264,26 @@ def main(argv: Iterable[str] | None = None) -> int: run_current_match_adminlog_refresh_loop( interval_seconds=args.interval, lookback_seconds=args.lookback_seconds, + lookback_minutes=args.lookback_minutes, max_runs=args.max_runs, ) return 0 +def _resolve_lookback_seconds( + *, + lookback_seconds: int | None = None, + lookback_minutes: int | None = None, +) -> int: + if lookback_minutes is not None: + if int(lookback_minutes) <= 0: + raise ValueError("lookback_minutes must be positive.") + return int(lookback_minutes) * 60 + if lookback_seconds is None: + return get_current_match_adminlog_lookback_seconds() + return int(lookback_seconds) + + def _emit_worker_event(event: str, **fields: object) -> None: print(json.dumps({"event": event, **fields}, indent=2, default=str), flush=True) diff --git a/backend/app/rcon_historical_storage.py b/backend/app/rcon_historical_storage.py index c0d8179..aa886a7 100644 --- a/backend/app/rcon_historical_storage.py +++ b/backend/app/rcon_historical_storage.py @@ -20,6 +20,9 @@ COMPETITIVE_WINDOW_GAP_SECONDS = 1800 COMPETITIVE_MODE_PARTIAL = "partial" COMPETITIVE_MODE_APPROXIMATE = "approximate" COMPETITIVE_MODE_EXACT = "exact" +RUNNING_HISTORICAL_CAPTURE_CONFLICT_MESSAGE = ( + "historical materialization capture already running" +) def initialize_rcon_historical_storage( @@ -72,6 +75,10 @@ def initialize_rcon_historical_storage( created_at TEXT NOT NULL DEFAULT CURRENT_TIMESTAMP ); + CREATE UNIQUE INDEX IF NOT EXISTS idx_rcon_historical_single_running_historical + ON rcon_historical_capture_runs(mode) + WHERE status = 'running' AND mode = 'historical'; + CREATE TABLE IF NOT EXISTS rcon_historical_samples ( id INTEGER PRIMARY KEY AUTOINCREMENT, target_id INTEGER NOT NULL, @@ -151,17 +158,22 @@ def start_rcon_historical_capture_run( resolved_path = initialize_rcon_historical_storage(db_path=db_path) with _connect(resolved_path) as connection: - cursor = connection.execute( - """ - INSERT INTO rcon_historical_capture_runs ( - mode, - status, - target_scope, - started_at - ) VALUES (?, 'running', ?, ?) - """, - (mode, target_scope, _utc_now_iso()), - ) + try: + cursor = connection.execute( + """ + INSERT INTO rcon_historical_capture_runs ( + mode, + status, + target_scope, + started_at + ) VALUES (?, 'running', ?, ?) + """, + (mode, target_scope, _utc_now_iso()), + ) + except sqlite3.IntegrityError as error: + if mode == "historical": + raise RuntimeError(RUNNING_HISTORICAL_CAPTURE_CONFLICT_MESSAGE) from error + raise return int(cursor.lastrowid) diff --git a/backend/app/rcon_historical_worker.py b/backend/app/rcon_historical_worker.py index 6a76993..d7c6f89 100644 --- a/backend/app/rcon_historical_worker.py +++ b/backend/app/rcon_historical_worker.py @@ -105,10 +105,47 @@ def run_rcon_historical_capture_unlocked( admin_log_lookback_minutes = get_rcon_admin_log_lookback_minutes() captured_at = utc_now().isoformat().replace("+00:00", "Z") target_scope = target_key or "all-configured-rcon-targets" - run_id = start_rcon_historical_capture_run( - mode=resolved_capture_mode, - target_scope=target_scope, - ) + try: + run_id = start_rcon_historical_capture_run( + mode=resolved_capture_mode, + target_scope=target_scope, + ) + except RuntimeError as error: + if _is_historical_run_conflict(error, capture_mode=resolved_capture_mode): + return { + "status": "skipped", + "run_status": "skipped", + "captured_at": captured_at, + "target_scope": target_scope, + "capture_mode": resolved_capture_mode, + "materialization_skipped": resolved_skip_materialization, + "admin_log_lookback_minutes": admin_log_lookback_minutes, + "admin_log_events_seen": 0, + "admin_log_events_inserted": 0, + "duplicate_events": 0, + "samples_inserted": 0, + "targets": [], + "errors": [], + "admin_log_errors": [], + "materialization_result": { + "status": "skipped", + "reason": "already-running", + }, + "storage_status": [], + "totals": { + "targets_seen": 0, + "samples_inserted": 0, + "duplicate_samples": 0, + "failed_targets": 0, + "admin_log_events_seen": 0, + "admin_log_events_inserted": 0, + "admin_log_duplicate_events": 0, + "admin_log_failed_targets": 0, + "materialized_matches_inserted": 0, + "materialized_matches_updated": 0, + }, + } + raise stats = RconHistoricalCaptureStats() items: list[dict[str, object]] = [] errors: list[dict[str, object]] = [] @@ -355,6 +392,12 @@ def _run_capture_with_retries( time.sleep(retry_delay_seconds) +def _is_historical_run_conflict(error: RuntimeError, *, capture_mode: str) -> bool: + return capture_mode == CAPTURE_MODE_HISTORICAL and ( + "already running" in str(error).lower() + ) + + def _select_targets(target_key: str | None) -> list[object]: configured_targets = list(load_rcon_targets()) if not configured_targets: diff --git a/backend/tests/test_current_match_payload.py b/backend/tests/test_current_match_payload.py index 16afdab..81b6c72 100644 --- a/backend/tests/test_current_match_payload.py +++ b/backend/tests/test_current_match_payload.py @@ -760,6 +760,7 @@ class CurrentMatchPublicEndpointHardeningTests(unittest.TestCase): "app.postgres_rcon_storage.connect_postgres_compat", return_value=connection_scope, ) as connect_postgres, + patch("app.rcon_admin_log_materialization.materialize_rcon_admin_log") as materialize, ): result = rcon_admin_log_storage.list_current_match_kill_feed( server_key="comunidad-hispana-01", @@ -767,6 +768,7 @@ class CurrentMatchPublicEndpointHardeningTests(unittest.TestCase): ) connect_postgres.assert_called_once_with(initialize=False) + materialize.assert_not_called() self.assertEqual(result["items"], []) def test_player_stats_postgres_read_only_does_not_initialize_storage(self) -> None: @@ -783,6 +785,7 @@ class CurrentMatchPublicEndpointHardeningTests(unittest.TestCase): "app.postgres_rcon_storage.connect_postgres_compat", return_value=connection_scope, ) as connect_postgres, + patch("app.rcon_admin_log_materialization.materialize_rcon_admin_log") as materialize, ): result = rcon_admin_log_storage.list_current_match_player_stats( server_key="comunidad-hispana-01", @@ -790,6 +793,7 @@ class CurrentMatchPublicEndpointHardeningTests(unittest.TestCase): ) connect_postgres.assert_called_once_with(initialize=False) + materialize.assert_not_called() self.assertEqual(result["items"], []) self.assertEqual(result["source"], "rcon-admin-log-current-match-summary") diff --git a/backend/tests/test_rcon_current_match_worker.py b/backend/tests/test_rcon_current_match_worker.py index 289dee9..8f6485d 100644 --- a/backend/tests/test_rcon_current_match_worker.py +++ b/backend/tests/test_rcon_current_match_worker.py @@ -14,6 +14,7 @@ from app.config import ( ) from app.rcon_current_match_worker import ( list_current_match_trusted_targets, + run_current_match_adminlog_refresh_loop, run_current_match_adminlog_refresh_once_unlocked, ) @@ -76,7 +77,7 @@ class RconCurrentMatchWorkerTests(unittest.TestCase): 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): + def fake_persist(*, target, entries, db_path=None, ensure_storage=True): persist_calls.append({"target": target, "entries": entries, "db_path": db_path}) return { "events_seen": len(entries), @@ -94,16 +95,50 @@ class RconCurrentMatchWorkerTests(unittest.TestCase): 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(persist_calls[0]["db_path"], None) self.assertEqual(result["totals"]["events_inserted"], 1) self.assertEqual(result["status"], "ok") + def test_once_unlocked_initializes_storage_once_and_persists_without_repeated_ddl(self) -> None: + persist_calls: list[dict[str, object]] = [] + + def fake_fetch(target, *, 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, ensure_storage=True): + persist_calls.append( + { + "target": target, + "entries": entries, + "db_path": db_path, + "ensure_storage": ensure_storage, + } + ) + return { + "events_seen": len(entries), + "events_inserted": len(entries), + "duplicate_events": 0, + } + + with patch("app.rcon_current_match_worker.initialize_rcon_admin_log_storage") as initialize: + result = run_current_match_adminlog_refresh_once_unlocked( + lookback_seconds=180, + targets=[TARGET_01], + fetch_entries_fn=fake_fetch, + persist_entries_fn=fake_persist, + ) + + initialize.assert_called_once_with(db_path=None) + self.assertEqual(persist_calls[0]["ensure_storage"], False) + 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): + def fake_persist(*, target, entries, db_path=None, ensure_storage=True): return { "events_seen": len(entries), "events_inserted": len(entries), @@ -155,6 +190,44 @@ class RconCurrentMatchWorkerTests(unittest.TestCase): self.assertEqual(second["totals"]["events_inserted"], 0) self.assertEqual(second["totals"]["duplicate_events"], 1) + def test_loop_honors_max_runs(self) -> None: + results = [{"status": "ok"}, {"status": "ok"}] + + with ( + patch("app.rcon_current_match_worker.initialize_rcon_admin_log_storage") as initialize, + patch( + "app.rcon_current_match_worker.run_current_match_adminlog_refresh_once", + side_effect=results, + ) as run_once, + patch("app.rcon_current_match_worker.time.sleep") as sleep, + ): + run_current_match_adminlog_refresh_loop( + interval_seconds=5, + lookback_seconds=900, + max_runs=2, + ) + + initialize.assert_called_once_with() + self.assertEqual(run_once.call_count, 2) + self.assertEqual(sleep.call_count, 1) + + def test_compose_nas_runs_split_live_worker_and_safe_historical_interval(self) -> None: + compose_path = os.path.join( + os.path.dirname(os.path.dirname(__file__)), + "..", + "deploy", + "portainer", + "docker-compose.nas.yml", + ) + with open(compose_path, encoding="utf-8") as handle: + compose_text = handle.read() + + self.assertIn("rcon-live-adminlog-worker:", compose_text) + self.assertIn("app.rcon_current_match_worker", compose_text) + self.assertIn('--lookback-minutes\n - "15"', compose_text) + self.assertIn('HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS: ${HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS:-900}', compose_text) + self.assertNotIn('HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS: ${HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS:-2}', compose_text) + def test_current_match_adminlog_config_defaults_and_overrides(self) -> None: with _temporary_env( CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS=None, diff --git a/backend/tests/test_rcon_historical_worker.py b/backend/tests/test_rcon_historical_worker.py index 028a0d8..bc4aa98 100644 --- a/backend/tests/test_rcon_historical_worker.py +++ b/backend/tests/test_rcon_historical_worker.py @@ -155,6 +155,21 @@ class RconHistoricalWorkerTests(unittest.TestCase): self.assertEqual(seen["timeout_seconds"], 3.5) + def test_historical_capture_skips_when_previous_heavy_run_is_still_running(self) -> None: + with ( + patch("app.rcon_historical_worker.initialize_rcon_historical_storage"), + patch("app.rcon_historical_worker._select_targets", return_value=[TARGET]), + patch( + "app.rcon_historical_worker.start_rcon_historical_capture_run", + side_effect=RuntimeError("historical materialization capture already running"), + ), + ): + payload = run_rcon_historical_capture_unlocked(capture_mode=CAPTURE_MODE_HISTORICAL) + + self.assertEqual(payload["status"], "skipped") + self.assertEqual(payload["run_status"], "skipped") + self.assertEqual(payload["materialization_result"]["reason"], "already-running") + @contextmanager def _temporary_env(**values: str): diff --git a/deploy/portainer/docker-compose.nas.yml b/deploy/portainer/docker-compose.nas.yml index c01edde..98f6db7 100644 --- a/deploy/portainer/docker-compose.nas.yml +++ b/deploy/portainer/docker-compose.nas.yml @@ -19,7 +19,7 @@ services: backend: build: context: ../../backend - environment: + environment: &backend_environment HLL_BACKEND_DATABASE_URL: ${HLL_BACKEND_DATABASE_URL:?HLL_BACKEND_DATABASE_URL is required} HLL_BACKEND_HOST: ${HLL_BACKEND_HOST:-0.0.0.0} HLL_BACKEND_PORT: ${HLL_BACKEND_PORT:-8000} @@ -70,11 +70,7 @@ services: context: ../../backend command: ["python", "-m", "app.historical_runner", "--hourly"] environment: - HLL_BACKEND_DATABASE_URL: ${HLL_BACKEND_DATABASE_URL:?HLL_BACKEND_DATABASE_URL is required} - HLL_BACKEND_LIVE_DATA_SOURCE: ${HLL_BACKEND_LIVE_DATA_SOURCE:-rcon} - HLL_BACKEND_HISTORICAL_DATA_SOURCE: ${HLL_BACKEND_HISTORICAL_DATA_SOURCE:-rcon} - HLL_BACKEND_RCON_TIMEOUT_SECONDS: ${HLL_BACKEND_RCON_TIMEOUT_SECONDS:-20} - HLL_BACKEND_RCON_TARGETS: ${HLL_BACKEND_RCON_TARGETS:?HLL_BACKEND_RCON_TARGETS is required} + <<: *backend_environment HLL_HISTORICAL_REFRESH_INTERVAL_SECONDS: ${HLL_HISTORICAL_REFRESH_INTERVAL_SECONDS:-3600} HLL_HISTORICAL_REFRESH_MAX_RETRIES: ${HLL_HISTORICAL_REFRESH_MAX_RETRIES:-2} HLL_HISTORICAL_REFRESH_RETRY_DELAY_SECONDS: ${HLL_HISTORICAL_REFRESH_RETRY_DELAY_SECONDS:-15} @@ -89,19 +85,57 @@ services: - hll-internal restart: unless-stopped + rcon-live-adminlog-worker: + profiles: + - advanced + build: + context: ../../backend + command: + - python + - -m + - app.rcon_current_match_worker + - loop + - --interval + - "5" + - --lookback-minutes + - "15" + environment: + <<: *backend_environment + CURRENT_MATCH_ADMINLOG_ENABLED: "true" + CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS: ${CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS:-5} + CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS: ${CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS:-900} + depends_on: + postgres: + condition: service_healthy + backend: + condition: service_started + volumes: + - backend-data:/app/data + networks: + - hll-internal + restart: unless-stopped + rcon-historical-worker: profiles: - advanced build: context: ../../backend - command: ["python", "-m", "app.rcon_historical_worker", "loop"] + command: + - python + - -m + - app.rcon_historical_worker + - loop + - --capture-mode + - historical + - --interval + - "900" + - --retries + - "2" + - --retry-delay + - "15" environment: - HLL_BACKEND_DATABASE_URL: ${HLL_BACKEND_DATABASE_URL:?HLL_BACKEND_DATABASE_URL is required} - HLL_BACKEND_LIVE_DATA_SOURCE: ${HLL_BACKEND_LIVE_DATA_SOURCE:-rcon} - HLL_BACKEND_HISTORICAL_DATA_SOURCE: ${HLL_BACKEND_HISTORICAL_DATA_SOURCE:-rcon} - HLL_BACKEND_RCON_TIMEOUT_SECONDS: ${HLL_BACKEND_RCON_TIMEOUT_SECONDS:-20} - HLL_BACKEND_RCON_TARGETS: ${HLL_BACKEND_RCON_TARGETS:?HLL_BACKEND_RCON_TARGETS is required} - HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS: ${HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS:-600} + <<: *backend_environment + HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS: ${HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS:-900} HLL_RCON_HISTORICAL_CAPTURE_MAX_RETRIES: ${HLL_RCON_HISTORICAL_CAPTURE_MAX_RETRIES:-2} HLL_RCON_HISTORICAL_CAPTURE_RETRY_DELAY_SECONDS: ${HLL_RCON_HISTORICAL_CAPTURE_RETRY_DELAY_SECONDS:-15} HLL_BACKEND_RCON_ADMIN_LOG_LOOKBACK_MINUTES: ${HLL_BACKEND_RCON_ADMIN_LOG_LOOKBACK_MINUTES:-10} diff --git a/docs/current-match-adminlog-freshness.md b/docs/current-match-adminlog-freshness.md index 597a226..172a6e1 100644 --- a/docs/current-match-adminlog-freshness.md +++ b/docs/current-match-adminlog-freshness.md @@ -1,160 +1,342 @@ # Current Match AdminLog Freshness -## Problem +## Production Evidence -The public current-match page was lagging because: +The current-match public feed was stale because the persisted AdminLog read model was coupled to slow historical materialization. -- `/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 production/runtime evidence: -Observed behavior from TASK-268 matched this design: +- `hll-vietnam-rcon-historical-worker-1` was running `python -m app.rcon_historical_worker loop` +- configured capture interval was `HLL_RCON_HISTORICAL_CAPTURE_INTERVAL_SECONDS=2` +- configured retries were `HLL_RCON_HISTORICAL_CAPTURE_MAX_RETRIES=2` and `HLL_RCON_HISTORICAL_CAPTURE_RETRY_DELAY_SECONDS=1` +- configured AdminLog lookback was `HLL_BACKEND_RCON_ADMIN_LOG_LOOKBACK_MINUTES=10` +- real `rcon_historical_capture_runs` durations were around `15-30` minutes instead of `2` seconds +- recent examples included: + - `40789`: `10:17:54 -> 10:33:45` + - `40790`: `10:33:44 -> 10:49:38` + - `40791`: `10:33:47 -> 11:05:20` + - `40792`: `11:05:19 -> 11:21:15` failed with PostgreSQL deadlock + - `40793`: `11:05:22` still running at inspection time +- each heavy cycle was also doing large historical work: + - `player_stats_seen` around `838k` + - `player_stats_materialized` around `838k` + - `materialized_matches_updated` around `392-394` -- checked-in historical worker interval: `600` seconds -- checked-in AdminLog lookback: `10` minutes -- observed public lag growing from about `333s` to about `651s` +This matters because: -## Solution +- `/api/current-match/kills` reads `rcon_admin_log_events` +- `/api/current-match/players` reads `rcon_admin_log_events` +- those endpoints do not query RCON/CRCON directly per public request +- if the worker cycle lasts longer than the AdminLog lookback window, new live events can be delayed or missed from the current-match API perspective -Add a dedicated lightweight worker: +The feed freshness problem was therefore primarily a backend ingestion architecture issue, not a frontend rendering issue. -- module: `python -m app.rcon_current_match_worker` -- scope: only trusted current-match servers +## Architecture Before + +Before this change, one worker path mixed three concerns: + +1. lightweight live sample capture +2. AdminLog ingestion +3. heavy historical materialization of matches, player stats, rankings and search inputs + +That design had two bad properties: + +- current-match freshness depended on heavy historical work finishing +- the heavy path could deadlock or overlap while still starving `rcon_admin_log_events` refreshes + +## Architecture After + +### Live AdminLog ingestion path + +- dedicated worker module: `python -m app.rcon_current_match_worker` +- scope: trusted current-match servers only - `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 +- cadence: explicit fast loop, intended for `5s` +- overlap safety: relies on idempotent AdminLog inserts and table uniqueness instead of the long historical writer lock +- output target: `rcon_admin_log_events` +- explicitly does not: + - run `materialize_rcon_admin_log` + - rebuild `rcon_match_player_stats` + - refresh annual rankings + - rebuild player search + - process hundreds of thousands of historical stat rows -Default worker settings: +Operational behavior: -- `CURRENT_MATCH_ADMINLOG_INTERVAL_SECONDS=10` -- `CURRENT_MATCH_ADMINLOG_LOOKBACK_SECONDS=180` -- `CURRENT_MATCH_ADMINLOG_ENABLED=false` +- worker startup initializes AdminLog storage once +- each loop iteration fetches recent AdminLog only +- each target is handled independently +- per-target results include: + - `target_key` + - `entries_seen` + - `events_inserted` + - `duplicate_events` + - `duration_ms` +- target failures are isolated and do not stop healthy targets -The worker is opt-in. This task does not change Compose to start it automatically. +### Historical materialization path -## Design Notes +- historical worker remains `python -m app.rcon_historical_worker loop` +- it now runs on an explicit safe interval in Portainer instead of inheriting a too-fast runtime cadence +- heavy materialization stays in the historical worker +- a single-running-historical guard was added through the capture-run storage layer +- if a historical run is already active, the next historical attempt returns a skipped result with reason `already-running` -The worker intentionally avoids: +### Schema and initialization behavior -- 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 +The hot live path was reduced in two places: -Each iteration: +- current-match API reads already use `ensure_storage=False`, so public `GET /api/current-match/kills` and `GET /api/current-match/players` do not request schema initialization on each read +- the live AdminLog worker now initializes storage once at worker startup or once-mode execution, then persists with `ensure_storage=False` -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 +This removes obvious repeated PostgreSQL DDL/init from the live ingestion loop. -## Run Commands +## Deployment Decision -Local one-shot validation: +The chosen deployment split in `deploy/portainer/docker-compose.nas.yml` is: -```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: +1. add a dedicated live worker service: ```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} +rcon-live-adminlog-worker: + command: + - python + - -m + - app.rcon_current_match_worker + - loop + - --interval + - "5" + - --lookback-minutes + - "15" ``` -The snippet is documented only. It is not applied automatically by this task. +2. keep the historical worker for heavy materialization, but force a safe cadence: -## Post-Deployment Validation +```yaml +rcon-historical-worker: + command: + - python + - -m + - app.rcon_historical_worker + - loop + - --capture-mode + - historical + - --interval + - "900" +``` -Watch worker logs for per-target counts and errors. The useful signals are: +Rationale: -- `entries_seen` -- `events_inserted` -- `duplicate_events` -- `target_key` -- `duration_ms` +- the repository already uses the historical worker for AdminLog-backed materialization +- `historical-runner` is not a drop-in replacement for `materialize_rcon_admin_log` +- the immediate production risk was heavy materialization running effectively every few seconds +- slowing the heavy worker to `900s` while moving live ingestion to a dedicated `5s` worker cleanly separates freshness from historical backfill/materialization cost -Sample the public API every 10 seconds: +Non-negotiable result: + +- no worker should be materializing `~838k` player-stat rows every `2` seconds +- live current-match freshness no longer depends on heavy historical materialization completing first + +## Current-Match API Read Path + +Confirmed after this change: + +- `/api/current-match/kills` reads from `rcon_admin_log_events` +- `/api/current-match/players` reads from `rcon_admin_log_events` +- those routes do not trigger `materialize_rcon_admin_log` +- those routes do not query RCON directly per public request +- those routes avoid repeated storage initialization through `ensure_storage=False` + +## Validation + +Code validation completed locally: + +- `python -m compileall backend/app` +- `cd backend; python -m unittest tests.test_current_match_payload` +- `cd backend; python -m unittest tests.test_rcon_historical_worker` +- `cd backend; python -m unittest tests.test_rcon_current_match_worker` + +Coverage added/updated for: + +- live worker one-shot persistence reuse +- live worker loop `max-runs` +- live worker one-time storage initialization with `ensure_storage=False` on hot writes +- live worker per-target failure isolation +- historical worker skip when a heavy run is already active +- compose split validation for live worker presence and historical safe interval +- current-match read paths remaining read-only and not triggering materialization + +## Post-Deploy Validation Commands + +### 1. Verify services ```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" +docker ps --format "table {{.Names}}\t{{.Image}}\t{{.Command}}\t{{.Status}}" +``` -1..18 | ForEach-Object { - $now = Get-Date - $ts = [DateTimeOffset]::UtcNow.ToUnixTimeMilliseconds() +### 2. Verify live worker command - $kills = Invoke-RestMethod "$killsBase&_ts=$ts" -Headers @{ "Cache-Control" = "no-cache"; "Pragma" = "no-cache" } - $killItems = @($kills.data.items) - $topKill = $killItems | Select-Object -First 1 +```powershell +docker inspect -f '{{.Path}} {{json .Args}}' hll-vietnam-rcon-live-adminlog-worker-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)" - } +Adapt the container name to the actual stack service name if needed. - $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) - } +### 3. Verify historical worker is no longer 2-second heavy materialization - [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 " | ") - } +```powershell +docker inspect -f '{{.Path}} {{json .Args}}' hll-vietnam-rcon-historical-worker-1 - Start-Sleep -Seconds 10 +docker inspect -f '{{range .Config.Env}}{{println .}}{{end}}' hll-vietnam-rcon-historical-worker-1 | sort | grep -Ei 'CAPTURE|CURRENT|RCON|ADMIN|MATERIAL|INTERVAL|RETRY|LOOKBACK|LOCK' +``` + +Expected: + +- no heavy materialization every `2` seconds +- historical interval should be safe if materialization remains in this service + +### 4. Live worker logs + +```powershell +docker logs --tail=200 hll-vietnam-rcon-live-adminlog-worker-1 +``` + +Expected: + +- short cycles +- per-target AdminLog counts +- no `player_stats_seen 838k` +- no `materialized_matches_updated` output every few seconds +- no repeated deadlocks + +### 5. Historical worker/materializer logs + +```powershell +docker logs --since 30m hll-vietnam-rcon-historical-worker-1 2>&1 | grep -Ei "deadlock|materialized|player_stats_seen|capture-cycle|error|exception|traceback" +``` + +Expected: + +- no repeated deadlocks +- no overlapping heavy cycles +- no heavy cycle every `2` seconds + +### 6. DB capture run sanity + +```powershell +docker exec -i hll-vietnam-postgres-1 psql -U hll_vietnam -d hll_vietnam -P pager=off -c " +SELECT + id, + mode, + status, + started_at, + completed_at, + targets_seen, + samples_inserted, + duplicate_samples, + failed_targets, + LEFT(COALESCE(notes,''), 160) AS notes +FROM rcon_historical_capture_runs +ORDER BY id DESC +LIMIT 20; +" +``` + +### 7. AdminLog freshness + +```powershell +docker exec -i hll-vietnam-postgres-1 psql -U hll_vietnam -d hll_vietnam -P pager=off -c " +SELECT + target_key, + event_type, + COUNT(*) AS n, + MAX(server_time) AS max_server_time, + MAX(event_timestamp) AS max_event_timestamp, + MAX(created_at) AS max_created_at +FROM rcon_admin_log_events +WHERE target_key IN ('comunidad-hispana-01', 'comunidad-hispana-02') + AND created_at >= now() - interval '15 minutes' +GROUP BY target_key, event_type +ORDER BY target_key, n DESC; +" +``` + +### 8. API validation from Windows PowerShell + +```powershell +cd "D:\Proyectos\HLL Vietnam" + +$servers = @("comunidad-hispana-01", "comunidad-hispana-02") + +foreach ($server in $servers) { + $ts = [DateTimeOffset]::UtcNow.ToUnixTimeMilliseconds() + + $kills = Invoke-RestMethod "https://comunidadhll.devzamode.es/api/current-match/kills?server=$server&limit=20&_ts=$ts" -Headers @{ + "Cache-Control" = "no-cache" + "Pragma" = "no-cache" + } + + $players = Invoke-RestMethod "https://comunidadhll.devzamode.es/api/current-match/players?server=$server&_ts=$ts" -Headers @{ + "Cache-Control" = "no-cache" + "Pragma" = "no-cache" + } + + "" + "===== $server =====" + + [PSCustomObject]@{ + server = $server + kills_scope = $kills.data.scope + kills_confidence = $kills.data.confidence + kills_count = @($kills.data.items).Count + kills_stale_filtered = $kills.data.stale_events_filtered + players_scope = $players.data.scope + players_confidence = $players.data.confidence + players_count = @($players.data.items).Count + players_updated_at = $players.data.updated_at + } + + "Latest kills:" + $kills.data.items | Select-Object -First 10 event_id,server_time,event_timestamp,killer_name,killer_team,victim_name,victim_team,weapon + + "Top players:" + $players.data.items | Sort-Object kills -Descending | Select-Object -First 10 player_name,team,kills,deaths,teamkills,deaths_by_teamkill,most_used_weapon } ``` -Expected outcome after deployment: +Expected acceptance after redeploy: -- 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 +- new CRCON kills should reach `rcon_admin_log_events` within roughly `5-30` seconds under normal conditions +- `/api/current-match/kills` should reflect them shortly after +- `/api/current-match/players` should also advance shortly after +- no worker should materialize `838k` player stats every few seconds +- repeated PostgreSQL deadlocks should stop + +## Known Remaining Issue + +`TEAM KILL` AdminLog parsing was left as follow-up work in this task. + +Known behavior: + +- parser currently recognizes `KILL:` but not the separate `TEAM KILL` label in some lines +- those lines can still land as `event_type="unknown"` +- that means some teamkills may remain absent from current-match feed/stats until a follow-up parser fix lands + +This was intentionally not expanded into the central scope of the ingestion/materialization split. + +## Risks And Rollback + +Primary residual risks: + +- a stale historical `running` row can cause later heavy cycles to skip until an operator clears the stale state +- if production has multiple unexpected worker replicas, logs should be reviewed after redeploy to confirm the split behaves as intended +- live freshness still depends on RCON AdminLog availability per target + +Rollback path: + +1. stop the dedicated `rcon-live-adminlog-worker` +2. restore the previous historical worker command/env in Portainer if required +3. redeploy the stack + +Rollback should only be used if the new live worker introduces unexpected operational issues, because the previous combined design is known to starve current-match freshness under heavy materialization load.