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

@@ -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)
 

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)

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):

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"):