fix(log): redact serials, add connection context, demote non-fault errors

.gitignore

@@ -109,3 +109,6 @@ ENV/
 
 # OS X
 .DS_Store
+
+# Local design specs / scratch (not for the repo)
+/docs/superpowers/

paradox/config.py

@@ -7,7 +7,7 @@
 class Config:
     DEFAULTS = {
         "LOGGING_LEVEL_CONSOLE": logging.INFO,  # See documentation of Logging package
-        "LOGGING_LEVEL_FILE": logging.ERROR,
+        "LOGGING_LEVEL_FILE": logging.WARNING,
         "LOGGING_FILE": (
             None,
             [type(None), str],

paradox/connections/ip/commands.py

@@ -1,9 +1,13 @@
 import binascii
 import logging
 
-from paradox.connections.ip.parsers import (IPMessageCommand, IPMessageRequest,
-                                            IPPayloadConnectResponse)
+from paradox.connections.ip.parsers import (
+    IPMessageCommand,
+    IPMessageRequest,
+    IPPayloadConnectResponse,
+)
 from paradox.exceptions import ConnectToIpModuleFailed, PAICriticalException
+from paradox.lib.utils import mask_secret
 
 logger = logging.getLogger("PAI").getChild(__name__)
 
@@ -93,9 +97,7 @@ async def _send_keep_alive_command(self):
         )
         await self.connection.send_raw_ip_message(msg)
         in_message = await self.connection.wait_for_ip_message()
-        logger.debug(
-            "Keep alive response: {}".format(binascii.hexlify(in_message.payload))
-        )
+        logger.debug(f"Keep alive response: {binascii.hexlify(in_message.payload)}")
 
     async def _authenticate_to_ip_module(self):
         logger.info("Authenticating with IP Module")
@@ -131,7 +133,7 @@ async def _authenticate_to_ip_module(self):
                 response.hardware_version,
                 response.ip_firmware_major,
                 response.ip_firmware_minor,
-                binascii.hexlify(response.ip_module_serial).decode("utf-8"),
+                mask_secret(response.ip_module_serial),
             )
         )
 

paradox/connections/ip/protocol.py

@@ -68,7 +68,7 @@ def _process_message(self, data):
         elif message.header.message_type == IPMessageType.ip_response:
             self.handler.on_ip_message(message)
         else:
-            logger.error(f"Wrong message detected: {message}")
+            logger.warning(f"Wrong message detected: {message}")
 
     def data_received(self, recv_data):
         for frame in self._framer.feed(recv_data):

paradox/connections/ip/stun_session.py

@@ -8,9 +8,31 @@
 
 from paradox.exceptions import ConnectToSiteFailed, StunSessionRefreshFailed
 from paradox.lib import stun
+from paradox.lib.utils import mask_email, mask_secret
 
 logger = logging.getLogger("PAI").getChild(__name__)
 
+SENSITIVE_SITE_INFO_KEYS = {
+    "panelSerial": mask_secret,
+    "email": mask_email,
+}
+
+
+def redact_site_info(value):
+    """Recursively mask serials and emails in the SWAN site listing."""
+    if isinstance(value, dict):
+        return {
+            k: (
+                SENSITIVE_SITE_INFO_KEYS[k](v)
+                if k in SENSITIVE_SITE_INFO_KEYS
+                else redact_site_info(v)
+            )
+            for k, v in value.items()
+        }
+    if isinstance(value, list):
+        return [redact_site_info(v) for v in value]
+    return value
+
 
 class StunSession:
     def __init__(self, site_id, email, panel_serial):
@@ -36,7 +58,9 @@ async def connect(self) -> None:
         if self.site_info is None:
             raise ConnectToSiteFailed("Unable to get site info")
 
-        logger.debug("Site Info: %s", json.dumps(self.site_info, indent=4))
+        logger.debug(
+            "Site Info: %s", json.dumps(redact_site_info(self.site_info), indent=4)
+        )
         self.module = self._select_module()
 
         if self.module is None:
@@ -102,7 +126,8 @@ def _select_module(self):
                     continue
 
                 logger.debug(
-                    "Found module with panel serial: %s", module["panelSerial"]
+                    "Found module with panel serial: %s",
+                    mask_secret(module["panelSerial"]),
                 )
 
                 if not self.panel_serial:  # Pick first available

paradox/hardware/evo/panel.py

@@ -248,7 +248,7 @@ async def control_partitions(self, partitions: list, command: str) -> bool:
                 parsers.PerformPartitionAction, args, reply_expected=0x4
             )
         except MappingError:
-            logger.error('Partition command: "%s" is not supported' % command)
+            logger.warning('Partition command: "%s" is not supported' % command)
             return False
 
         if reply:
@@ -275,7 +275,7 @@ async def control_zones(self, zones: list, command: str) -> bool:
                 parsers.PerformZoneAction, args, reply_expected=0xD
             )
         except MappingError:
-            logger.error('Zone command: "%s" is not supported' % command)
+            logger.warning('Zone command: "%s" is not supported' % command)
             return False
 
         if reply:
@@ -299,7 +299,7 @@ async def control_outputs(self, outputs, command) -> bool:
                 parsers.PerformPGMAction, args, reply_expected=0x4
             )
         except MappingError:
-            logger.error('PGM command: "%s" is not supported' % command)
+            logger.warning('PGM command: "%s" is not supported' % command)
             return False
 
         if reply:
@@ -308,15 +308,19 @@ async def control_outputs(self, outputs, command) -> bool:
             logger.info('PGM command: "%s" failed' % command)
         return reply is not None
 
-    async def control_module_pgm_outputs(self, module_address: int, pgm_index: int, command: str) -> bool:
+    async def control_module_pgm_outputs(
+        self, module_address: int, pgm_index: int, command: str
+    ) -> bool:
         """
         Control PGM module outputs
         :param int module_address: bus address of the PGM module
         :param int pgm_index: 1-4 index of the PGM output
         :param str command: textual command
         :return: True if accepted
         """
-        assert 1 <= pgm_index <= parsers.MODULE_PGM_PACKET_SLOTS, "pgm_index must be between 1 and %d" % parsers.MODULE_PGM_PACKET_SLOTS
+        assert 1 <= pgm_index <= parsers.MODULE_PGM_PACKET_SLOTS, (
+            "pgm_index must be between 1 and %d" % parsers.MODULE_PGM_PACKET_SLOTS
+        )
         pgm_commands = ["release"] * parsers.MODULE_PGM_PACKET_SLOTS
         pgm_commands[pgm_index - 1] = command
 
@@ -326,7 +330,7 @@ async def control_module_pgm_outputs(self, module_address: int, pgm_index: int,
                 parsers.PerformModulePGMAction, args, reply_expected=0xA
             )
         except MappingError:
-            logger.error('Module PGM command: "%s" is not supported' % command)
+            logger.warning('Module PGM command: "%s" is not supported' % command)
             return False
 
         if reply:
@@ -350,7 +354,7 @@ async def control_doors(self, doors, command) -> bool:
                 parsers.PerformDoorAction, args, reply_expected=0x4
             )
         except MappingError:
-            logger.error('Door command: "%s" is not supported' % command)
+            logger.warning('Door command: "%s" is not supported' % command)
             return False
 
         if reply:

paradox/hardware/panel.py

@@ -338,7 +338,7 @@ def handle_status(message: Container, parser_map):
         mvars = message.fields.value
 
         if mvars.address not in parser_map:
-            logger.error(
+            logger.warning(
                 "Parser for memory address ({}) is not implemented. "
                 "Skipping.".format(mvars.address)
             )

paradox/hardware/prt3/panel.py

@@ -440,12 +440,12 @@ def _build_partition_cmd(
         """
         if command == "disarm":
             if not user_code:
-                logger.error("PRT3: disarm requires PRT3_USER_CODE to be configured")
+                logger.warning("PRT3: disarm requires PRT3_USER_CODE to be configured")
                 return None
             try:
                 return encoder.encode_disarm(partition, user_code), f"AD{partition:03d}"
             except ValueError as exc:
-                logger.error("PRT3: invalid PRT3_USER_CODE for disarm: %s", exc)
+                logger.warning("PRT3: invalid PRT3_USER_CODE for disarm: %s", exc)
                 return None
 
         if command in _QUICK_ARM_MODES:
@@ -457,11 +457,11 @@ def _build_partition_cmd(
                         f"AA{partition:03d}",
                     )
                 except ValueError as exc:
-                    logger.error("PRT3: invalid PRT3_USER_CODE for arm: %s", exc)
+                    logger.warning("PRT3: invalid PRT3_USER_CODE for arm: %s", exc)
                     return None
             return encoder.encode_quick_arm(partition, mode), f"AQ{partition:03d}"
 
-        logger.error("PRT3: unknown partition command %r", command)
+        logger.warning("PRT3: unknown partition command %r", command)
         return None
 
     async def control_partitions(self, partitions: list, command: str) -> bool:
@@ -535,7 +535,7 @@ async def send_panic(self, partitions: list, panic_type: str, _code) -> bool:
         """
         encode_fn = _PANIC_ENCODERS.get(panic_type)
         if encode_fn is None:
-            logger.error("PRT3: unknown panic type %r", panic_type)
+            logger.warning("PRT3: unknown panic type %r", panic_type)
             return False
 
         accepted = False

paradox/interfaces/mqtt/basic.py

@@ -26,7 +26,7 @@ def mqtt_handle_decorator(
     func: typing.Callable[
         ["BasicMQTTInterface", ParsedMessage],
         typing.Coroutine[None, "BasicMQTTInterface", ParsedMessage],
-    ]
+    ],
 ):
     async def try_func(*args, **kwargs):
         try:
@@ -65,7 +65,7 @@ def wrapper(
             topics = topic.split("/")
 
             if len(topics) < 3:
-                logger.error(f"Invalid topic in mqtt message: {message.topic}")
+                logger.warning(f"Invalid topic in mqtt message: {message.topic}")
                 return
 
             content = message.payload.decode("utf-8").strip()
@@ -377,12 +377,12 @@ async def _mqtt_handle_utility_key(self, prep: ParsedMessage):
         """PRT3-only: trigger a utility key (UK{nnn}). Payload is ignored."""
         topics = prep.topics
         if len(topics) < 4:
-            logger.error("PRT3 utility key: malformed topic %r", topics)
+            logger.warning("PRT3 utility key: malformed topic %r", topics)
             return
         try:
             key = int(topics[3])
         except (ValueError, TypeError):
-            logger.error("PRT3 utility key: invalid key number %r", topics[3])
+            logger.warning("PRT3 utility key: invalid key number %r", topics[3])
             return
 
         message = f"Utility key command: key={key}"

paradox/interfaces/mqtt/core.py

@@ -10,7 +10,6 @@
 
 from paho.mqtt.client import (
     LOGGING_LEVEL,
-    MQTT_ERR_SUCCESS,
     CallbackAPIVersion,
     Client,
     MQTTv5,
@@ -186,7 +185,7 @@ def register(self, cls):
         # set up correctly.
         if self.connected and self._last_connect_args is not None:
             try:
-                if hasattr(cls, "on_connect") and callable(getattr(cls, "on_connect")):
+                if hasattr(cls, "on_connect") and callable(cls.on_connect):
                     cls.on_connect(*self._last_connect_args)
             except Exception:
                 logger.exception(
@@ -214,28 +213,49 @@ def _report_pai_status(self, status):
             retain=True,
         )
 
-    def _on_connect_cb(self, client, userdata, connect_flags, reason_code, properties=None):
+    def _on_connect_cb(
+        self, client, userdata, connect_flags, reason_code, properties=None
+    ):
         # called on Thread-6
         if not reason_code.is_failure:
             logger.info("MQTT Broker Connected")
             self.state = ConnectionState.CONNECTED
-            self._last_connect_args = (client, userdata, connect_flags, reason_code, properties)
+            self._last_connect_args = (
+                client,
+                userdata,
+                connect_flags,
+                reason_code,
+                properties,
+            )
             self._report_pai_status(self._last_pai_status)
-            self._call_registars("on_connect", client, userdata, connect_flags, reason_code, properties)
+            self._call_registars(
+                "on_connect", client, userdata, connect_flags, reason_code, properties
+            )
         else:
             logger.error(
                 f"Failed to connect to MQTT: {connack_string(reason_code)} ({reason_code})"
             )
 
-    def _on_disconnect_cb(self, client, userdata, disconnect_flags, reason_code, properties=None):
+    def _on_disconnect_cb(
+        self, client, userdata, disconnect_flags, reason_code, properties=None
+    ):
         # called on Thread-6
         if not reason_code.is_failure:
             logger.info("MQTT Broker Disconnected")
         else:
-            logger.error(f"MQTT Broker unexpectedly disconnected. Code: {reason_code}")
+            logger.warning(
+                f"MQTT Broker unexpectedly disconnected. Code: {reason_code}"
+            )
 
         self.state = ConnectionState.NEW
-        self._call_registars("on_disconnect", self.client, userdata, disconnect_flags, reason_code, properties)
+        self._call_registars(
+            "on_disconnect",
+            self.client,
+            userdata,
+            disconnect_flags,
+            reason_code,
+            properties,
+        )
 
     def disconnect(self, reasoncode=None, properties=None):
         self.state = ConnectionState.DISCONNECTING
@@ -320,7 +340,9 @@ def subscribe_callback(self, sub, callback: typing.Callable):
         self.mqtt.message_callback_add(sub, callback)
         self.mqtt.subscribe(sub)
 
-    def on_disconnect(self, client, userdata, disconnect_flags, reason_code, properties=None):
+    def on_disconnect(
+        self, client, userdata, disconnect_flags, reason_code, properties=None
+    ):
         """Called from MQTT connection"""
         pass
 

paradox/lib/handlers.py

@@ -125,4 +125,4 @@ async def handle(self, data) -> None:
                 cmd = data.fields.value.po.command
             except AttributeError:
                 cmd = repr(data)
-            logger.error("No handler for message %s\nDetail: %s", cmd, data)
+            logger.warning("No handler for message %s\nDetail: %s", cmd, data)