From 67448388507838f81317e02a0c67ed1fb7e054e5 Mon Sep 17 00:00:00 2001 From: catborise Date: Mon, 26 Oct 2026 21:47:01 +0300 Subject: [PATCH] fix(console): a serial console worker's failure reaches socketiod's log - The worker told why a console did not open or closed only in the user's terminal (as users see errors: a host that cannot be reached is not named). It now also logs the full reason to socketiod's own stderr, the journal or docker logs, which socketiod hands it as a descriptor. - A refused token says the link has expired or the user may no longer open the console: a valid link for a user who lost access was told only that it had expired. - A send that takes nothing (0 bytes) waits like a busy stream instead of spinning. --- conf/daemon/consolecallback | 14 +++++++++++++- console/socketiod | 7 +++++-- console/tests/test_socketiod.py | 4 ++-- console/tests/test_socketiod_child.py | 7 ++++++- 4 files changed, 26 insertions(+), 6 deletions(-) diff --git a/conf/daemon/consolecallback b/conf/daemon/consolecallback index ea9eccf5..72bd344f 100755 --- a/conf/daemon/consolecallback +++ b/conf/daemon/consolecallback @@ -6,6 +6,7 @@ # socketiod made the terminal raw before starting it (setting it here would # drop what the user typed meanwhile). +import logging import os import sys import time @@ -34,6 +35,9 @@ SEND_WAIT = 5 # seconds a paste may wait for the VM to take it ACCESS_CHECK = 10 # seconds between checks that the user may still use the console +log = logging.getLogger("consolecallback") + + def say(text): os.write(1, ("\r\n[%s]\r\n" % text).encode()) @@ -82,7 +86,7 @@ def from_client(watch, fd, events, console): # a non-blocking stream takes part of a paste, or none (-2) while the VM is busy while data and stream is not None and time.monotonic() < deadline: sent = stream.send(data) - if sent == -2: + if sent <= 0: # -2: busy; 0 cannot advance either time.sleep(0.01) else: data = data[sent:] @@ -113,6 +117,11 @@ def may_still_open(user_id, instance): def main(): + # what the operator reads goes to socketiod's log (the journal, docker + # logs), on the descriptor it names; the user's terminal gets a short line + if os.environ.get("CONSOLECALLBACK_LOG_FD"): + log.addHandler(logging.StreamHandler(os.fdopen(int(os.environ["CONSOLECALLBACK_LOG_FD"]), "w", buffering=1))) + log.propagate = False instance = Instance.objects.select_related("compute").get(pk=int(sys.argv[1])) user_id = int(sys.argv[2]) c = instance.compute @@ -120,6 +129,7 @@ def main(): console = Console(connection_manager.get_connection(c.hostname, c.login, c.password, c.type), instance.uuid) console.check() except libvirt.libvirtError as err: + log.warning("serial console of VM %s did not open: %s", instance.name, err) say("Cannot open the console of %s: %s" % (instance.name, public_error_text(err))) sys.exit(1) if console.stream is None: @@ -132,10 +142,12 @@ def main(): console.check() if time.monotonic() - checked > ACCESS_CHECK: if not may_still_open(user_id, instance): + log.info("serial console of VM %s closed: its user may no longer open it", instance.name) say("You may no longer open this console") sys.exit(1) checked = time.monotonic() except libvirt.libvirtError as err: # the host went away, the VM was undefined or migrated + log.warning("serial console of VM %s closed: %s", instance.name, err) say("The console of %s closed: %s" % (instance.name, public_error_text(err))) sys.exit(1) diff --git a/console/socketiod b/console/socketiod index 63c8683c..1529f5e9 100755 --- a/console/socketiod +++ b/console/socketiod @@ -34,6 +34,7 @@ from django.conf import settings # noqa: E402 from console.tokens import authorize # noqa: E402 CONSOLECALLBACK = os.path.join(ROOT_PATH, "conf", "daemon", "consolecallback") +LOG_FD = os.dup(2) # this daemon's stderr: a worker logs there on its fd 3 MAX_SESSIONS = 20 logger = logging.getLogger("socketiod") @@ -62,7 +63,7 @@ def connect(sid, environ, auth): try: instance, user = authorize((auth or {}).get("token")) except PermissionError: - raise refused("The console link has expired: reload the page") + raise refused("The console link has expired, or you may no longer open this console: reload the page") finally: db.close_old_connections() taken = None @@ -81,7 +82,9 @@ def connect(sid, environ, auth): try: # pty.fork's master is inheritable: without this each worker would # hold the other sessions' consoles open - os.closerange(3, os.sysconf("SC_OPEN_MAX")) + os.dup2(LOG_FD, 3) + os.closerange(4, os.sysconf("SC_OPEN_MAX")) + os.environ["CONSOLECALLBACK_LOG_FD"] = "3" os.execv(sys.executable, [sys.executable, CONSOLECALLBACK, str(instance.pk), str(user.pk)]) finally: os._exit(1) diff --git a/console/tests/test_socketiod.py b/console/tests/test_socketiod.py index dc997db3..f6665812 100644 --- a/console/tests/test_socketiod.py +++ b/console/tests/test_socketiod.py @@ -242,8 +242,8 @@ class WorkerIsolationTestCase(Base): while b"]" not in output: select.select([fd], [], [], 5) output += os.read(fd, 1024) - # 0-2: its terminal, 3: the listing itself - self.assertEqual(output.decode().strip(), "['0', '1', '2', '3']") + # 0-2: its terminal, 3: socketiod's log, 4: the listing itself + self.assertEqual(output.decode().strip(), "['0', '1', '2', '3', '4']") def _open(fd): diff --git a/console/tests/test_socketiod_child.py b/console/tests/test_socketiod_child.py index c4353b2f..148c4bb4 100644 --- a/console/tests/test_socketiod_child.py +++ b/console/tests/test_socketiod_child.py @@ -70,8 +70,9 @@ def start_socketiod(test): port = free_port() env = dict(os.environ, DJANGO_SETTINGS_MODULE="socketiod_test_settings", PYTHONPATH=os.pathsep.join([tmp.name, str(ROOT)])) + test.log = Path(tmp.name) / "socketiod.log" # its stderr, as the journal would have it server = subprocess.Popen([sys.executable, str(SOCKETIOD), "-H", "127.0.0.1", "-p", str(port)], - cwd=ROOT, env=env, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL) + cwd=ROOT, env=env, stdout=subprocess.DEVNULL, stderr=test.log.open("w")) test.addCleanup(lambda: (server.kill(), server.wait())) end = time.monotonic() + 20 while time.monotonic() < end: @@ -125,6 +126,10 @@ class SocketiodProcessTestCase(TransactionTestCase): time.sleep(0.05) self.assertEqual(consoles(self.server.pid), []) self.assertIsNone(self.server.poll()) + # the operator finds why in socketiod's log, with the details the user is not shown + log = self.log.read_text() + for name in self.tokens: + self.assertIn("serial console of VM %s did not open" % name, log) def test_a_client_without_a_valid_token_is_refused(self): for token in ("", "22-no-such-vm"):