fix(console): the console daemons log where the operator looks

- novncd and socketiod log to stderr: the journal on hosts, docker logs in
  the container (runit no longer sends them to unrotated files under
  /var/log). Django's settings gave them the panel's own log file, which
  every process rotated on its own, and made novncd's -v and -d have no
  effect; both work again.
- A refused console says why in the log: novncd's denials are warnings
  (they were shown only with -v), socketiod logs each refusal and who
  opened which VM's serial console.
- The README's serial console notes say what #228 changed (access
  re-checked, superuser takeover, reasons) and where the logs are.

README.md

@@ -412,8 +412,9 @@ A VM without graphics (no `<graphics>` device, a `<console type='pty'>`) opens a
 - The VM page's Settings → Console switches a shut-off VM between VNC and serial (Console type). A new VNC console takes the form's other fields; on a TCP or TLS compute it needs Listen on: All interfaces (only SSH computes reach a localhost console).
 - The guest must use its serial port: a login prompt needs `systemctl enable --now serial-getty@ttyS0`, boot messages need the kernel parameter `console=ttyS0,115200`. The console shows only what the guest writes after it opens; press Enter for a new prompt.
 - socketiod listens on 127.0.0.1:6081; the page reaches it through nginx's `/socket.io/` location on the panel's own address.
-- It accepts the console page's signed token, as noVNC does: whoever gets that token within 120 s gets the console, and an open console stays open after its user loses access to the VM.
-- One console per VM, at most 20 at a time; a second one shows "refused".
+- It accepts the console page's signed token, as noVNC does: whoever gets that token within 120 s gets the console. An open console closes within 10 s once its user loses access to the VM.
+- One console per VM, at most 20 at a time; a second one is refused with the reason, except a superuser's, which takes the console over.
+- novncd and socketiod log to the journal (`journalctl -u webvirt-novncd -u webvirt-socketiod`) or, in Docker, to `docker logs`: a console that was refused or could not connect says why there.
 
 ## Updating
 

conf/runit/novncd.sh

@@ -1,4 +1,5 @@
 #!/bin/sh
 
 cd /srv/webvirtcloud || exit 1
-exec /sbin/setuser www-data /srv/webvirtcloud/venv/bin/python3 /srv/webvirtcloud/console/novncd >> /var/log/novncd.log 2>&1
+# its log goes to the container's output (docker logs)
+exec /sbin/setuser www-data /srv/webvirtcloud/venv/bin/python3 /srv/webvirtcloud/console/novncd 2>&1

conf/runit/socketiod.sh

@@ -2,4 +2,5 @@
 # The serial console daemon; it refuses connections while SERIAL_CONSOLE_ENABLED is off.
 
 cd /srv/webvirtcloud || exit 1
-exec /sbin/setuser www-data /srv/webvirtcloud/venv/bin/python3 /srv/webvirtcloud/console/socketiod >> /var/log/socketiod.log 2>&1
+# its log goes to the container's output (docker logs)
+exec /sbin/setuser www-data /srv/webvirtcloud/venv/bin/python3 /srv/webvirtcloud/console/socketiod 2>&1

console/novncd

@@ -58,22 +58,18 @@ def get_connection_infos(token):
     from console.tokens import authorize
     from vrtManager.instance import wvmInstance
 
-    try:
-        instance, _user = authorize(token)
-        conn = wvmInstance(
-            instance.compute.hostname,
-            instance.compute.login,
-            instance.compute.password,
-            instance.compute.type,
-            instance.name,
-            uuid=instance.uuid,  # the VM access was checked for, whatever its name now
-        )
-        console_host = conn.get_console_listener_addr()
-        console_port = conn.get_console_port()
-        console_socket = conn.get_console_socket()
-    except Exception as e:
-        logging.error("Fail to retrieve console connection infos: %s", e)
-        raise
+    instance, _user = authorize(token)
+    conn = wvmInstance(
+        instance.compute.hostname,
+        instance.compute.login,
+        instance.compute.password,
+        instance.compute.type,
+        instance.name,
+        uuid=instance.uuid,  # the VM access was checked for, whatever its name now
+    )
+    console_host = conn.get_console_listener_addr()
+    console_port = conn.get_console_port()
+    console_socket = conn.get_console_socket()
     compute = instance.compute
     return compute.hostname, compute.login, compute.type, console_host, console_port, console_socket
 
@@ -98,13 +94,13 @@ class ConsoleClient:
         # is shared by the browser's tabs and would name the last console opened
         token = parse_qs(urlparse(self.path).query).get("token", [None])[0]
         if not token:
-            self.msg("No console token in the websocket URL")
+            logging.warning("Console connection without a token in its websocket URL")
             return
 
         try:
             connhost, connuser, conntype, console_host, console_port, console_socket = get_connection_infos(token)
         except Exception as e:
-            self.msg("Console connection denied: %s" % e)
+            logging.warning("Console connection denied: %s", e)
             return
         logging.debug(
             "Console of %s@%s (type %s): %s:%s, socket %s",
@@ -160,14 +156,12 @@ class ConsoleProxyHandler(ProxyRequestHandler, ConsoleClient):
 if __name__ == "__main__":
     options = get_parser().parse_args()
 
-    FORMAT = "%(asctime)s - %(name)s - %(levelname)s : %(message)s"
-    if options.debug:
-        logging.basicConfig(level=logging.DEBUG, format=FORMAT)
-        options.verbose = True
-    elif options.verbose:
-        logging.basicConfig(level=logging.INFO, format=FORMAT)
-    else:
-        logging.basicConfig(level=logging.WARNING, format=FORMAT)
+    # to stderr (the journal, docker logs), not the panel's own log file:
+    # each process rotating that file would lose lines. force: Django's
+    # settings already gave the root logger that file.
+    level = logging.DEBUG if options.debug else logging.INFO if options.verbose else logging.WARNING
+    logging.basicConfig(level=level, format="%(levelname)s %(name)s: %(message)s", force=True)
+    options.verbose = options.verbose or options.debug
 
     # nginx ends TLS: novncd speaks plain websockets on the loopback
     WebSocketProxy(

console/socketiod

@@ -7,6 +7,7 @@
 import argparse
 import codecs
 import fcntl
+import logging
 import os
 import pty
 import select
@@ -34,6 +35,7 @@ from console.tokens import authorize  # noqa: E402
 CONSOLECALLBACK = os.path.join(ROOT_PATH, "conf", "daemon", "consolecallback")
 MAX_SESSIONS = 20
 
+logger = logging.getLogger("socketiod")
 sio = socketio.Server(async_mode="threading")  # the same origin only
 # Handlers run on their own threads. sessions (sid -> {"pid", "fd", "vm",
 # "lock", "open"}) changes only under sessions_lock; a session's fd is used
@@ -43,24 +45,30 @@ sessions = {}
 sessions_lock = threading.Lock()
 
 
+def refused(reason):
+    """The refusal the page shows; it is logged too."""
+    logger.info("serial console refused: %s", reason)
+    return socketio.exceptions.ConnectionRefusedError(reason)
+
+
 @sio.event
 def connect(sid, environ, auth):
     # the page shows the reason
     if not settings.SERIAL_CONSOLE_ENABLED:
-        raise socketio.exceptions.ConnectionRefusedError("The serial console is turned off on this server")
+        raise refused("The serial console is turned off on this server")
     try:
         instance, user = authorize((auth or {}).get("token"))
     except PermissionError:
-        raise socketio.exceptions.ConnectionRefusedError("The console link has expired: reload the page")
+        raise refused("The console link has expired: reload the page")
     finally:
         db.close_old_connections()
     taken = None
     with sessions_lock:
         open_sid = next((s for s, session in sessions.items() if session["vm"] == instance.pk), None)
         if open_sid is not None and not user.is_superuser:
-            raise socketio.exceptions.ConnectionRefusedError("The console of this VM is open in another window")
+            raise refused("The console of this VM is open in another window")
         if open_sid is None and len(sessions) >= MAX_SESSIONS:
-            raise socketio.exceptions.ConnectionRefusedError("Too many consoles are open on this server: try again later")
+            raise refused("Too many consoles are open on this server: try again later")
         if open_sid is not None:  # a superuser takes over a console left open
             taken = open_sid, sessions.pop(open_sid)
         pid, fd = pty.fork()
@@ -73,6 +81,8 @@ def connect(sid, environ, auth):
             finally:
                 os._exit(1)
         sessions[sid] = session = {"pid": pid, "fd": fd, "vm": instance.pk, "lock": threading.Lock(), "open": True}
+    logger.info("serial console of VM %s opened by %s%s", instance.name, user.username,
+                " (taken over)" if taken else "")
     if taken:
         old_sid, old_session = taken
         sio.emit("pty_output", {"output": "\r\n[An administrator opened this console]\r\n"}, to=old_sid)
@@ -183,4 +193,7 @@ if __name__ == "__main__":
     parser.add_argument("-H", "--host", default=settings.SOCKETIO_HOST, help="Listen host")
     parser.add_argument("-p", "--port", type=int, default=settings.SOCKETIO_PORT, help="Listen port")
     options = parser.parse_args()
+    # to stderr (the journal, docker logs), not the panel's own log file:
+    # each process rotating that file would lose lines
+    logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s", force=True)
     Server(options.host, options.port).run()

console/tests/test_socketiod.py

@@ -91,8 +91,10 @@ class SocketiodTestCase(Base):
         self.assertEqual(self.started[0][0], self.d.forward)
 
     def refused(self, sid, auth):
-        with self.assertRaises(self.d.socketio.exceptions.ConnectionRefusedError) as refusal:
+        with self.assertRaises(self.d.socketio.exceptions.ConnectionRefusedError) as refusal, \
+                self.assertLogs("socketiod", level="INFO") as log:  # the reason is logged too
             self.d.connect(sid, {}, auth)
+        self.assertIn(refusal.exception.error_args["message"], log.output[0])
         return refusal.exception.error_args["message"]
 
     def test_refused_connections_start_nothing_and_say_why(self):

console/tests/test_views.py

@@ -577,12 +577,13 @@ class NovncdDaemonLogicTestCase(TestCase):
         handler.msg = MagicMock()
 
         socket_factory = MagicMock()
-        # Should cleanly exit and log message without raising UnboundLocalError
-        handler._new_client(socket_factory=socket_factory)
+        # a refusal is a warning: it shows in the log without -v
+        with self.assertLogs(level="WARNING") as log:
+            handler._new_client(socket_factory=socket_factory)
 
         mock_get_info.assert_not_called()
         socket_factory.assert_not_called()
-        handler.msg.assert_called_with("No console token in the websocket URL")
+        self.assertIn("without a token", log.output[0])
 
     @patch("console.tokens.authorize")
     @patch("vrtManager.instance.wvmInstance")