Add logging to device matching

src/main/python/main.py

@@ -12,6 +12,9 @@ from constants import WINDOW_WIDTH, WINDOW_HEIGHT
 
 
 # http://timlehr.com/python-exception-hooks-with-qt-message-box/
+from util import init_logger
+
+
 def show_exception_box(log_msg):
     if QtWidgets.QApplication.instance() is not None:
         errorbox = QtWidgets.QMessageBox()
@@ -52,6 +55,7 @@ if __name__ == '__main__':
         linux_keystroke_recorder()
     else:
         appctxt = ApplicationContext()       # 1. Instantiate ApplicationContext
+        init_logger()
         qt_exception_hook = UncaughtHook()
         window = MainWindow()
         window.resize(WINDOW_WIDTH, WINDOW_HEIGHT)

src/main/python/util.py

@@ -1,7 +1,10 @@
 # SPDX-License-Identifier: GPL-2.0-or-later
+import logging
+import os
 import time
+from logging.handlers import RotatingFileHandler
 
-from PyQt5.QtCore import QCoreApplication
+from PyQt5.QtCore import QCoreApplication, QStandardPaths
 
 from hidproxy import hid
 
@@ -49,25 +52,35 @@ def hid_send(dev, msg, retries=1):
 
 def is_rawhid(desc):
     if desc["usage_page"] != 0xFF60 or desc["usage"] != 0x61:
+        logging.warning("is_rawhid: {} does not match - usage_page={:04X} usage={:02X}".format(
+            desc["path"], desc["usage_page"], desc["usage"]))
         return False
 
     dev = hid.device()
 
     try:
         dev.open_path(desc["path"])
-    except OSError:
+    except OSError as e:
+        logging.warning("is_rawhid: {} does not match - open_path error {}".format(desc["path"], e))
         return False
 
     # probe VIA version and ensure it is supported
     data = b""
     try:
         data = hid_send(dev, b"\x01", retries=3)
-    except RuntimeError:
+    except RuntimeError as e:
+        logging.warning("is_rawhid: {} does not match - hid_send error {}".format(desc["path"], e))
         pass
     dev.close()
 
     # must have VIA protocol version = 9
-    return data[0:3] == b"\x01\x00\x09"
+    if data[0:3] != b"\x01\x00\x09":
+        logging.warning("is_rawhid: {} does not match - unexpected data in response {}".format(
+            desc["path"], data.hex()))
+        return False
+
+    logging.info("is_rawhid: {} matched OK".format(desc["path"]))
+    return True
 
 
 def find_vial_devices(via_stack_json, sideload_vid=None, sideload_pid=None):
@@ -75,14 +88,29 @@ def find_vial_devices(via_stack_json, sideload_vid=None, sideload_pid=None):
 
     filtered = []
     for dev in hid.enumerate():
-        if dev["vendor_id"] == sideload_vid and dev["product_id"] == sideload_pid and is_rawhid(dev):
+        if dev["vendor_id"] == sideload_vid and dev["product_id"] == sideload_pid:
-            filtered.append(VialKeyboard(dev, sideload=True))
+            logging.info("Trying VID={:04X}, PID={:04X}, serial={}, path={} - sideload".format(
-        elif VIAL_SERIAL_NUMBER_MAGIC in dev["serial_number"] and is_rawhid(dev):
+                dev["vendor_id"], dev["product_id"], dev["serial_number"], dev["path"]
-            filtered.append(VialKeyboard(dev))
+            ))
+            if is_rawhid(dev):
+                filtered.append(VialKeyboard(dev, sideload=True))
+        elif VIAL_SERIAL_NUMBER_MAGIC in dev["serial_number"]:
+            logging.info("Matching VID={:04X}, PID={:04X}, serial={}, path={} - vial serial magic".format(
+                dev["vendor_id"], dev["product_id"], dev["serial_number"], dev["path"]
+            ))
+            if is_rawhid(dev):
+                filtered.append(VialKeyboard(dev))
         elif VIBL_SERIAL_NUMBER_MAGIC in dev["serial_number"]:
+            logging.info("Matching VID={:04X}, PID={:04X}, serial={}, path={} - vibl serial magic".format(
+                dev["vendor_id"], dev["product_id"], dev["serial_number"], dev["path"]
+            ))
             filtered.append(VialBootloader(dev))
-        elif str(dev["vendor_id"] * 65536 + dev["product_id"]) in via_stack_json["definitions"] and is_rawhid(dev):
+        elif str(dev["vendor_id"] * 65536 + dev["product_id"]) in via_stack_json["definitions"]:
-            filtered.append(VialKeyboard(dev, via_stack=True))
+            logging.info("Matching VID={:04X}, PID={:04X}, serial={}, path={} - VIA stack".format(
+                dev["vendor_id"], dev["product_id"], dev["serial_number"], dev["path"]
+            ))
+            if is_rawhid(dev):
+                filtered.append(VialKeyboard(dev, via_stack=True))
 
     if sideload_vid == sideload_pid == 0:
         filtered.append(VialDummyKeyboard())
@@ -100,3 +128,14 @@ def pad_for_vibl(msg):
     if len(msg) > 64:
         raise RuntimeError("vibl message too long")
     return msg + b"\x00" * (64 - len(msg))
+
+
+def init_logger():
+    logging.basicConfig(level=logging.INFO)
+    directory = QStandardPaths.writableLocation(QStandardPaths.AppLocalDataLocation)
+    if not os.path.exists(directory):
+        os.mkdir(directory)
+    path = os.path.join(directory, "vial.log")
+    handler = RotatingFileHandler(path, maxBytes=5 * 1024 * 1024, backupCount=5)
+    handler.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s - %(module)s:%(lineno)d - %(message)s"))
+    logging.getLogger().addHandler(handler)