more vnc debug

3 files changed, 81 insertions, 69 deletions

diff --git a/kvmd/apps/vnc/rfb/__init__.py b/kvmd/apps/vnc/rfb/__init__.py
index d1b56eee..d0b4da37 100644
--- a/kvmd/apps/vnc/rfb/__init__.py
+++ b/kvmd/apps/vnc/rfb/__init__.py
@@ -165,41 +165,42 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
         assert self._encodings.has_tight
         assert self._encodings.tight_jpeg_quality > 0
         assert len(data) <= 4194303, len(data)
-        await self._write_fb_update(self._width, self._height, RfbEncodings.TIGHT, drain=False)
+        await self._write_fb_update("JPEG FBUR", self._width, self._height, RfbEncodings.TIGHT, drain=False)
         length = len(data)
         if length <= 127:
-            await self._write_struct("", bytes([0b10011111, length & 0x7F]), data)
+            length_bytes = bytes([0b10011111, length & 0x7F])
         elif length <= 16383:
-            await self._write_struct("", bytes([0b10011111, length & 0x7F | 0x80, length >> 7 & 0x7F]), data)
+            length_bytes = bytes([0b10011111, length & 0x7F | 0x80, length >> 7 & 0x7F])
         else:
-            await self._write_struct("", bytes([0b10011111, length & 0x7F | 0x80, length >> 7 & 0x7F | 0x80, length >> 14 & 0xFF]), data)
+            length_bytes = bytes([0b10011111, length & 0x7F | 0x80, length >> 7 & 0x7F | 0x80, length >> 14 & 0xFF])
+        await self._write_struct("JPEG length + data", "", length_bytes, data)
         self.__reset_h264 = True
 
     async def _send_fb_h264(self, data: bytes) -> None:
         assert self._encodings.has_h264
         assert len(data) <= 0xFFFFFFFF, len(data)
-        await self._write_fb_update(self._width, self._height, RfbEncodings.H264, drain=False)
-        await self._write_struct("LL", len(data), int(self.__reset_h264), drain=False)
-        await self._write_struct("", data)
+        await self._write_fb_update("H264 FBUR", self._width, self._height, RfbEncodings.H264, drain=False)
+        await self._write_struct("H264 length + flags", "LL", len(data), int(self.__reset_h264), drain=False)
+        await self._write_struct("H264 data", "", data)
         self.__reset_h264 = False
 
     async def _send_resize(self, width: int, height: int) -> None:
         assert self._encodings.has_resize
-        await self._write_fb_update(width, height, RfbEncodings.RESIZE)
+        await self._write_fb_update("resize FBUR", width, height, RfbEncodings.RESIZE)
         self._width = width
         self._height = height
         self.__reset_h264 = True
 
     async def _send_rename(self, name: str) -> None:
         assert self._encodings.has_rename
-        await self._write_fb_update(0, 0, RfbEncodings.RENAME, drain=False)
-        await self._write_reason(name)
+        await self._write_fb_update("new server name FBUR", 0, 0, RfbEncodings.RENAME, drain=False)
+        await self._write_reason("new server name data", name)
         self.__name = name
 
     async def _send_leds_state(self, caps: bool, scroll: bool, num: bool) -> None:
         assert self._encodings.has_leds_state
-        await self._write_fb_update(0, 0, RfbEncodings.LEDS_STATE, drain=False)
-        await self._write_struct("B", int(scroll) | int(num) << 1 | int(caps) << 2)
+        await self._write_fb_update("new LEDs state FBUR", 0, 0, RfbEncodings.LEDS_STATE, drain=False)
+        await self._write_struct("new LEDs state data", "B", int(scroll) | int(num) << 1 | int(caps) << 2)
 
     # =====
 
@@ -208,9 +209,9 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
         # Version 3.5 was wrongly reported by some clients, but it should be
         # interpreted by all servers as 3.3
 
-        await self._write_struct("", b"RFB 003.008\n")
+        await self._write_struct("handshake server version", "", b"RFB 003.008\n")
 
-        response = await self._read_text(12)
+        response = await self._read_text("handshake client version", 12)
         if (
             not response.startswith("RFB 003.00")
             or not response.endswith("\n")
@@ -237,13 +238,13 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
             sec_types[2] = ("VNCAuth", self.__handshake_security_vnc_auth)
         if not sec_types:
             msg = "The client uses a very old protocol 3.3 and VNCAuth or NoneAuth is disabled"
-            await self._write_struct("L", 0, drain=False)  # Refuse old clients using the invalid security type
-            await self._write_reason(msg)
+            await self._write_struct("refusing security type flag", "L", 0, drain=False)
+            await self._write_reason("refusing security type reason", msg)
             raise RfbError(msg)
 
-        await self._write_struct("B" + "B" * len(sec_types), len(sec_types), *sec_types)  # Keep dict priority
+        await self._write_struct("security types", "B" + "B" * len(sec_types), len(sec_types), *sec_types)  # Keep dict priority
 
-        sec_type = await self._read_number("B")
+        sec_type = await self._read_number("selected security type", "B")
         if sec_type not in sec_types:
             raise RfbError(f"Invalid security type: {sec_type}")
 
@@ -252,14 +253,14 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
         await handler()
 
     async def __handshake_security_vencrypt(self) -> None:  # pylint: disable=too-many-branches
-        await self._write_struct("BB", 0, 2)  # VeNCrypt 0.2
+        await self._write_struct("VeNCrypt server version", "BB", 0, 2)  # VeNCrypt 0.2
 
-        vencrypt_version = "%d.%d" % (await self._read_struct("BB"))
+        vencrypt_version = "%d.%d" % (await self._read_struct("VeNCrypt client version", "BB"))
         if vencrypt_version != "0.2":
-            await self._write_struct("B", 1)  # Unsupported
+            await self._write_struct("VeNCrypt version refusing", "B", 1)  # Unsupported
             raise RfbError(f"Unsupported VeNCrypt version: {vencrypt_version}")
 
-        await self._write_struct("B", 0)
+        await self._write_struct("VeNCrypt version OK", "B", 0)
 
         if self.__none_auth_only:
             auth_types = {1: ("VeNCrypt/None", 0, self.__handshake_security_none)}
@@ -284,9 +285,9 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
                         auth_types[261] = ("VeNCrypt/X509VNCAuth", 2, self.__handshake_security_vnc_auth)
                     auth_types[258] = ("VeNCrypt/TLSVNCAuth", 1, self.__handshake_security_vnc_auth)
 
-        await self._write_struct("B" + "L" * len(auth_types), len(auth_types), *auth_types)
+        await self._write_struct("VeNCrypt auth types list", "B" + "L" * len(auth_types), len(auth_types), *auth_types)
 
-        auth_type = await self._read_number("L")
+        auth_type = await self._read_number("selected VeNCrype auth type", "L")
         if auth_type not in auth_types:
             raise RfbError(f"Invalid VeNCrypt auth type: {auth_type}")
 
@@ -295,7 +296,7 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
 
         if tls:
             assert self.__tls_ciphers, (self.__tls_ciphers, auth_name, tls, handler)
-            await self._write_struct("B", 1)  # Ack
+            await self._write_struct("VeNCrypt TLS Ack", "B", 1)  # Ack
             ssl_context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
             if tls == 2:
                 assert self.__x509_cert_path
@@ -306,9 +307,9 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
         await handler()
 
     async def __handshake_security_vencrypt_userpass(self) -> None:
-        (user_length, passwd_length) = await self._read_struct("LL")
-        user = (await self._read_text(user_length)).strip()
-        passwd = await self._read_text(passwd_length)
+        (user_length, passwd_length) = await self._read_struct("VeNCrypt user/passwd length", "LL")
+        user = (await self._read_text("VeNCrypt user", user_length)).strip()
+        passwd = await self._read_text("VeNCrypt passwd", passwd_length)
 
         allow = await self._authorize_userpass(user, passwd)
         if allow:
@@ -331,10 +332,10 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
 
     async def __handshake_security_vnc_auth(self) -> None:
         challenge = rfb_make_challenge()
-        await self._write_struct("", challenge)
+        await self._write_struct("VNCAuth challenge request", "", challenge)
 
         user = ""
-        response = (await self._read_struct("16s"))[0]
+        response = (await self._read_struct("VNCAuth challenge response", "16s"))[0]
         for passwd in self.__vnc_passwds:
             passwd_bytes = passwd.encode("utf-8", errors="ignore")
             if rfb_encrypt_challenge(challenge, passwd_bytes) == response:
@@ -353,20 +354,21 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
     async def __handshake_security_send_result(self, allow: bool, allow_msg: str, deny_msg: str, deny_reason: str) -> None:
         if allow:
             get_logger(0).info("[main] %s: %s", self._remote, allow_msg)
-            await self._write_struct("L", 0)
+            await self._write_struct("access OK", "L", 0)
         else:
-            await self._write_struct("L", 1, drain=(self.__rfb_version < 8))
+            await self._write_struct("access denial flag", "L", 1, drain=(self.__rfb_version < 8))
             if self.__rfb_version >= 8:
-                await self._write_reason(deny_reason)
+                await self._write_reason("access denial reason", deny_reason)
             raise RfbError(deny_msg)
 
     # =====
 
     async def __handshake_init(self) -> None:
-        await self._read_number("B")  # Shared flag, ignored
+        await self._read_number("initial shared flag", "B")  # Shared flag, ignored
 
-        await self._write_struct("HH", self._width, self._height, drain=False)
+        await self._write_struct("initial FB size", "HH", self._width, self._height, drain=False)
         await self._write_struct(
+            "initial pixel format",
             "BB?? HHH BBB xxx",
             32,     # Bits per pixel
             24,     # Depth
@@ -380,7 +382,7 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
             0,      # Blue shift
             drain=False,
         )
-        await self._write_reason(self.__name)
+        await self._write_reason("initial server name", self.__name)
 
     # =====
 
@@ -395,7 +397,7 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
             255: self.__handle_qemu_event,
         }
         while True:
-            msg_type = await self._read_number("B")
+            msg_type = await self._read_number("incoming message type", "B")
             handler = handlers.get(msg_type)
             if handler is not None:
                 await handler()  # type: ignore  # mypy bug
@@ -404,38 +406,38 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
 
     async def __handle_set_pixel_format(self) -> None:
         # JpegCompression may only be used when bits-per-pixel is either 16 or 32
-        bits_per_pixel = (await self._read_struct("xxx BB?? HHH BBB xxx"))[0]
+        bits_per_pixel = (await self._read_struct("pixel format", "xxx BB?? HHH BBB xxx"))[0]
         if bits_per_pixel not in [16, 32]:
             raise RfbError(f"Requested unsupported bits_per_pixel={bits_per_pixel} for Tight JPEG; required 16 or 32")
 
     async def __handle_set_encodings(self) -> None:
         logger = get_logger(0)
 
-        encodings_count = (await self._read_struct("x H"))[0]
+        encodings_count = (await self._read_struct("encodings number", "x H"))[0]
         if encodings_count > 1024:
             raise RfbError(f"Too many encodings: {encodings_count}")
 
-        self._encodings = RfbClientEncodings(frozenset(await self._read_struct("l" * encodings_count)))
+        self._encodings = RfbClientEncodings(frozenset(await self._read_struct("encodings list", "l" * encodings_count)))
         logger.info("[main] %s: Client features (SetEncodings): ...", self._remote)
         for (key, value) in dataclasses.asdict(self._encodings).items():
             logger.info("[main] %s: ... %s=%s", self._remote, key, value)
         self.__check_tight_jpeg()
 
         if self._encodings.has_ext_keys:  # Preferred method
-            await self._write_fb_update(0, 0, RfbEncodings.EXT_KEYS, drain=True)
+            await self._write_fb_update("ExtKeys FBUR", 0, 0, RfbEncodings.EXT_KEYS, drain=True)
         await self._on_set_encodings()
 
     async def __handle_fb_update_request(self) -> None:
         self.__check_tight_jpeg()  # If we don't receive SetEncodings from client
-        await self._read_struct("? HH HH")  # Ignore any arguments, just perform the full update
+        await self._read_struct("FBUR", "? HH HH")  # Ignore any arguments, just perform the full update
         await self._on_fb_update_request()
 
     async def __handle_key_event(self) -> None:
-        (state, code) = await self._read_struct("? xx L")
+        (state, code) = await self._read_struct("key event", "? xx L")
         await self._on_key_event(code, state)  # type: ignore
 
     async def __handle_pointer_event(self) -> None:
-        (buttons, to_x, to_y) = await self._read_struct("B HH")
+        (buttons, to_x, to_y) = await self._read_struct("pointer event", "B HH")
         await self._on_pointer_event(
             buttons={
                 "left": bool(buttons & 0x1),
@@ -453,12 +455,12 @@ class RfbClient(RfbClientStream):  # pylint: disable=too-many-instance-attribute
         )
 
     async def __handle_client_cut_text(self) -> None:
-        length = (await self._read_struct("xxx L"))[0]
-        text = await self._read_text(length)
+        length = (await self._read_struct("cut text length", "xxx L"))[0]
+        text = await self._read_text("cut text data", length)
         await self._on_cut_event(text)
 
     async def __handle_qemu_event(self) -> None:
-        (sub_type, state, code) = await self._read_struct("B H xxxx L")
+        (sub_type, state, code) = await self._read_struct("QEMU event (key?)", "B H xxxx L")
         if sub_type != 0:
             raise RfbError(f"Invalid QEMU sub-message type: {sub_type}")
         if code == 0xB7:
diff --git a/kvmd/apps/vnc/rfb/errors.py b/kvmd/apps/vnc/rfb/errors.py
index a5bb17e3..1cf68818 100644
--- a/kvmd/apps/vnc/rfb/errors.py
+++ b/kvmd/apps/vnc/rfb/errors.py
@@ -20,10 +20,14 @@
 # ========================================================================== #
 
 
+from .... import tools
+
+
+# =====
 class RfbError(Exception):
     pass
 
 
 class RfbConnectionError(RfbError):
-    def __init__(self, err: Exception) -> None:
-        super().__init__(type(err).__name__)
+    def __init__(self, msg: str, err: Exception) -> None:
+        super().__init__(f"{msg}: {tools.efmt(err)}")
diff --git a/kvmd/apps/vnc/rfb/stream.py b/kvmd/apps/vnc/rfb/stream.py
index 3aaa24e7..ee42436e 100644
--- a/kvmd/apps/vnc/rfb/stream.py
+++ b/kvmd/apps/vnc/rfb/stream.py
@@ -25,7 +25,7 @@ import ssl
 import struct
 
 from typing import Tuple
-from typing import Any
+from typing import Union
 
 from .... import aiotools
 
@@ -46,7 +46,7 @@ class RfbClientStream:
 
     # =====
 
-    async def _read_number(self, fmt: str) -> int:
+    async def _read_number(self, msg: str, fmt: str) -> int:
         assert len(fmt) == 1
         try:
             if fmt == "B":
@@ -55,51 +55,54 @@ class RfbClientStream:
                 fmt = f">{fmt}"
                 return struct.unpack(fmt, await self.__reader.readexactly(struct.calcsize(fmt)))[0]
         except (ConnectionError, asyncio.IncompleteReadError) as err:
-            raise RfbConnectionError(err)
+            raise RfbConnectionError(f"Can't read {msg}", err)
 
-    async def _read_struct(self, fmt: str) -> Tuple[int, ...]:
+    async def _read_struct(self, msg: str, fmt: str) -> Tuple[int, ...]:
         assert len(fmt) > 1
         try:
             fmt = f">{fmt}"
             return struct.unpack(fmt, (await self.__reader.readexactly(struct.calcsize(fmt))))
         except (ConnectionError, asyncio.IncompleteReadError) as err:
-            raise RfbConnectionError(err)
+            raise RfbConnectionError(f"Can't read {msg}", err)
 
-    async def _read_text(self, length: int) -> str:
+    async def _read_text(self, msg: str, length: int) -> str:
         try:
             return (await self.__reader.readexactly(length)).decode("utf-8", errors="ignore")
         except (ConnectionError, asyncio.IncompleteReadError) as err:
-            raise RfbConnectionError(err)
+            raise RfbConnectionError(f"Can't read {msg}", err)
 
     # =====
 
-    async def _write_struct(self, fmt: str, *values: Any, drain: bool=True) -> None:
+    async def _write_struct(self, msg: str, fmt: str, *values: Union[int, bytes], drain: bool=True) -> None:
         try:
             if not fmt:
                 for value in values:
+                    assert isinstance(value, bytes)
                     self.__writer.write(value)
             elif fmt == "B":
                 assert len(values) == 1
+                assert isinstance(values[0], int)
                 self.__writer.write(bytes([values[0]]))
             else:
                 self.__writer.write(struct.pack(f">{fmt}", *values))
             if drain:
                 await self.__writer.drain()
         except ConnectionError as err:
-            raise RfbConnectionError(err)
+            raise RfbConnectionError(f"Can't write {msg}", err)
 
-    async def _write_reason(self, text: str, drain: bool=True) -> None:
+    async def _write_reason(self, msg: str, text: str, drain: bool=True) -> None:
         encoded = text.encode("utf-8", errors="ignore")
-        await self._write_struct("L", len(encoded), drain=False)
+        await self._write_struct(msg, "L", len(encoded), drain=False)
         try:
             self.__writer.write(encoded)
             if drain:
                 await self.__writer.drain()
         except ConnectionError as err:
-            raise RfbConnectionError(err)
+            raise RfbConnectionError(f"Can't write {msg}", err)
 
-    async def _write_fb_update(self, width: int, height: int, encoding: int, drain: bool=True) -> None:
+    async def _write_fb_update(self, msg: str, width: int, height: int, encoding: int, drain: bool=True) -> None:
         await self._write_struct(
+            msg,
             "BxH HH HH l",
             0,  # FB update
             1,  # Number of rects
@@ -115,13 +118,16 @@ class RfbClientStream:
         ssl_reader = asyncio.StreamReader()
         protocol = asyncio.StreamReaderProtocol(ssl_reader)
 
-        transport = await loop.start_tls(
-            self.__writer.transport,
-            protocol,
-            ssl_context,
-            server_side=True,
-            ssl_handshake_timeout=ssl_timeout,
-        )
+        try:
+            transport = await loop.start_tls(
+                self.__writer.transport,
+                protocol,
+                ssl_context,
+                server_side=True,
+                ssl_handshake_timeout=ssl_timeout,
+            )
+        except ConnectionError as err:
+            raise RfbConnectionError("Can't start TLS", err)
 
         ssl_reader.set_transport(transport)
         ssl_writer = asyncio.StreamWriter(