|
| 1 | +"""Real-time backend log streaming over Socket.IO (admin only). |
| 2 | +
|
| 3 | +Pieces: |
| 4 | +- ``connect`` handler on the main socket server: resolves the session user and, |
| 5 | + if they are an admin, joins them to the ``admin`` room. It never rejects a |
| 6 | + connection, so the existing scan/sync sockets keep working for everyone. |
| 7 | +- ``start_log_forwarder``: a single background task (Redis-lock guarded) that |
| 8 | + subscribes to the ``romm:logs`` pub/sub channel — fed by ``LogStreamHandler`` |
| 9 | + in every backend process — and relays each line to the ``admin`` room. |
| 10 | +- ``get_recent_logs``: reads the capped ring buffer for backfill on view open. |
| 11 | +""" |
| 12 | + |
| 13 | +import asyncio |
| 14 | +import uuid |
| 15 | +from http.cookies import SimpleCookie |
| 16 | +from typing import Any, Final |
| 17 | + |
| 18 | +import socketio # type: ignore |
| 19 | + |
| 20 | +from config import REDIS_URL |
| 21 | +from handler.database import db_user_handler |
| 22 | +from handler.redis_handler import async_cache |
| 23 | +from handler.socket_handler import socket_handler |
| 24 | +from logger.log_stream_handler import LOG_BUFFER_KEY, LOG_CHANNEL |
| 25 | +from logger.logger import log |
| 26 | +from models.user import Role |
| 27 | +from utils import json_module |
| 28 | + |
| 29 | +ADMIN_ROOM: Final = "admin" |
| 30 | +FORWARDER_LOCK_KEY: Final = "romm:logs:forwarder" |
| 31 | +FORWARDER_LOCK_TTL: Final = 30 # seconds |
| 32 | +# Session cookie name configured on RedisSessionMiddleware in main.py. |
| 33 | +SESSION_COOKIE_NAME: Final = "romm_session" |
| 34 | + |
| 35 | + |
| 36 | +async def _session_from_environ(environ: dict[str, Any]) -> dict[str, Any]: |
| 37 | + """Resolve the auth session for a socket handshake. |
| 38 | +
|
| 39 | + Tries the session the middleware attached to the ASGI scope first; if it's |
| 40 | + absent (scope not propagated to the mounted socket app), falls back to |
| 41 | + parsing the session cookie and reading the session straight from Redis — |
| 42 | + the same lookup RedisSessionMiddleware performs. |
| 43 | + """ |
| 44 | + scope = environ.get("asgi.scope", {}) |
| 45 | + session = scope.get("session") |
| 46 | + if session: |
| 47 | + return session |
| 48 | + |
| 49 | + raw_cookie = environ.get("HTTP_COOKIE", "") |
| 50 | + if not raw_cookie: |
| 51 | + return {} |
| 52 | + |
| 53 | + cookie: SimpleCookie = SimpleCookie() |
| 54 | + cookie.load(raw_cookie) |
| 55 | + morsel = cookie.get(SESSION_COOKIE_NAME) |
| 56 | + if morsel is None: |
| 57 | + return {} |
| 58 | + |
| 59 | + session_data = await async_cache.get(f"session:{morsel.value}") |
| 60 | + if not session_data: |
| 61 | + return {} |
| 62 | + try: |
| 63 | + return json_module.loads(session_data) |
| 64 | + except Exception: # noqa: BLE001 - malformed session is "no session" |
| 65 | + return {} |
| 66 | + |
| 67 | + |
| 68 | +@socket_handler.socket_server.on("connect") # type: ignore |
| 69 | +async def connect(sid: str, environ: dict[str, Any], auth: Any = None) -> None: |
| 70 | + """Join admin users to the log-streaming room on socket connect. |
| 71 | +
|
| 72 | + Always returns ``None`` (accepts the connection) — only the room membership |
| 73 | + is gated, so the existing scan/sync sockets keep working for everyone. |
| 74 | + """ |
| 75 | + try: |
| 76 | + session = await _session_from_environ(environ) |
| 77 | + if session.get("iss") != "romm:auth": |
| 78 | + return |
| 79 | + |
| 80 | + username = session.get("sub") |
| 81 | + if not username: |
| 82 | + return |
| 83 | + |
| 84 | + user = db_user_handler.get_user_by_username(username) |
| 85 | + if user and user.enabled and user.role == Role.ADMIN: |
| 86 | + await socket_handler.socket_server.enter_room(sid, ADMIN_ROOM) |
| 87 | + except Exception: # noqa: BLE001 - never let auth resolution refuse a socket |
| 88 | + log.exception("Failed to resolve admin for log stream connect") |
| 89 | + |
| 90 | + |
| 91 | +async def get_recent_logs(limit: int) -> list[dict[str, Any]]: |
| 92 | + """Return the most recent buffered log lines in chronological order.""" |
| 93 | + raw = await async_cache.lrange(LOG_BUFFER_KEY, 0, max(0, limit - 1)) |
| 94 | + entries: list[dict[str, Any]] = [] |
| 95 | + for item in raw: |
| 96 | + try: |
| 97 | + entries.append(json_module.loads(item)) |
| 98 | + except Exception: # noqa: BLE001 - skip any malformed buffer entry |
| 99 | + continue |
| 100 | + # The buffer is newest-first (LPUSH); callers want oldest-first. |
| 101 | + entries.reverse() |
| 102 | + return entries |
| 103 | + |
| 104 | + |
| 105 | +async def start_log_forwarder() -> None: |
| 106 | + """Relay log lines from Redis pub/sub to admin Socket.IO clients. |
| 107 | +
|
| 108 | + Guarded by a Redis lock so that, when more than one web worker is running |
| 109 | + (WEB_SERVER_CONCURRENCY > 1), exactly one forwards and clients don't receive |
| 110 | + duplicate lines. |
| 111 | + """ |
| 112 | + lock_id = str(uuid.uuid4()) |
| 113 | + pubsub = None |
| 114 | + # Write-only manager for emitting — the same proven path scan/sync use. It |
| 115 | + # publishes the room emit to Redis; the main socket server's read-side |
| 116 | + # manager resolves `admin` room membership and delivers. Created inside the |
| 117 | + # running loop (like sync.py) rather than at import time. |
| 118 | + socket_manager = socketio.AsyncRedisManager(REDIS_URL, write_only=True) |
| 119 | + try: |
| 120 | + while True: |
| 121 | + got_lock = await async_cache.set( |
| 122 | + FORWARDER_LOCK_KEY, lock_id, nx=True, ex=FORWARDER_LOCK_TTL |
| 123 | + ) |
| 124 | + if not got_lock: |
| 125 | + # Another worker owns the forwarder; check back periodically in |
| 126 | + # case it dies and the lock expires. |
| 127 | + await asyncio.sleep(FORWARDER_LOCK_TTL / 2) |
| 128 | + continue |
| 129 | + |
| 130 | + pubsub = async_cache.pubsub() |
| 131 | + await pubsub.subscribe(LOG_CHANNEL) |
| 132 | + log.info("Log stream forwarder started") |
| 133 | + try: |
| 134 | + while True: |
| 135 | + # Heartbeat the lock so a healthy forwarder keeps ownership. |
| 136 | + await async_cache.set( |
| 137 | + FORWARDER_LOCK_KEY, lock_id, xx=True, ex=FORWARDER_LOCK_TTL |
| 138 | + ) |
| 139 | + message = await pubsub.get_message( |
| 140 | + ignore_subscribe_messages=True, |
| 141 | + timeout=FORWARDER_LOCK_TTL / 3, |
| 142 | + ) |
| 143 | + if not message: |
| 144 | + continue |
| 145 | + data = message.get("data") |
| 146 | + if not data: |
| 147 | + continue |
| 148 | + # One bad message or emit must not kill the forwarder — |
| 149 | + # swallow per-line and keep relaying. |
| 150 | + try: |
| 151 | + payload = json_module.loads(data) |
| 152 | + await socket_manager.emit( |
| 153 | + "logs:entry", payload, room=ADMIN_ROOM |
| 154 | + ) |
| 155 | + except Exception: # noqa: BLE001 - skip; keep forwarding |
| 156 | + continue |
| 157 | + finally: |
| 158 | + await pubsub.unsubscribe(LOG_CHANNEL) |
| 159 | + await pubsub.aclose() # type: ignore[attr-defined] |
| 160 | + pubsub = None |
| 161 | + except asyncio.CancelledError: |
| 162 | + if pubsub is not None: |
| 163 | + await pubsub.aclose() # type: ignore[attr-defined] |
| 164 | + # Release the lock on shutdown so a restart (e.g. uvicorn --reload) |
| 165 | + # resumes forwarding immediately instead of waiting out the TTL. |
| 166 | + await _release_lock(lock_id) |
| 167 | + raise |
| 168 | + except Exception: # noqa: BLE001 - never let the forwarder kill the app |
| 169 | + log.exception("Log forwarder crashed") |
| 170 | + await _release_lock(lock_id) |
| 171 | + |
| 172 | + |
| 173 | +async def _release_lock(lock_id: str) -> None: |
| 174 | + """Delete the forwarder lock only if we still own it.""" |
| 175 | + try: |
| 176 | + current = await async_cache.get(FORWARDER_LOCK_KEY) |
| 177 | + if current == lock_id: |
| 178 | + await async_cache.delete(FORWARDER_LOCK_KEY) |
| 179 | + except Exception: # noqa: BLE001 - best-effort cleanup |
| 180 | + pass |
0 commit comments