diff --git a/.gitignore b/.gitignore index 8050a2b7..67baa5c5 100644 --- a/.gitignore +++ b/.gitignore @@ -109,3 +109,6 @@ ENV/ # OS X .DS_Store + +# Local design specs / scratch (not for the repo) +/docs/superpowers/ diff --git a/paradox/config.py b/paradox/config.py index 7287f70f..26d8eef4 100644 --- a/paradox/config.py +++ b/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], diff --git a/paradox/connections/ip/commands.py b/paradox/connections/ip/commands.py index 8fd771ef..8372f722 100644 --- a/paradox/connections/ip/commands.py +++ b/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), ) ) diff --git a/paradox/connections/ip/protocol.py b/paradox/connections/ip/protocol.py index a0012095..4f90a870 100644 --- a/paradox/connections/ip/protocol.py +++ b/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): diff --git a/paradox/connections/ip/stun_session.py b/paradox/connections/ip/stun_session.py index 9d1d03ba..4c6a00ed 100644 --- a/paradox/connections/ip/stun_session.py +++ b/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 diff --git a/paradox/hardware/evo/panel.py b/paradox/hardware/evo/panel.py index 10202530..d5285729 100644 --- a/paradox/hardware/evo/panel.py +++ b/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,7 +308,9 @@ 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 @@ -316,7 +318,9 @@ async def control_module_pgm_outputs(self, module_address: int, pgm_index: int, :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: diff --git a/paradox/hardware/panel.py b/paradox/hardware/panel.py index 0f3ab558..622321a0 100644 --- a/paradox/hardware/panel.py +++ b/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) ) diff --git a/paradox/hardware/prt3/panel.py b/paradox/hardware/prt3/panel.py index d61f8049..6f3469b4 100644 --- a/paradox/hardware/prt3/panel.py +++ b/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 diff --git a/paradox/interfaces/mqtt/basic.py b/paradox/interfaces/mqtt/basic.py index e049c3fb..2538de09 100644 --- a/paradox/interfaces/mqtt/basic.py +++ b/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}" diff --git a/paradox/interfaces/mqtt/core.py b/paradox/interfaces/mqtt/core.py index 3a6dfd4d..cce16951 100644 --- a/paradox/interfaces/mqtt/core.py +++ b/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 diff --git a/paradox/lib/handlers.py b/paradox/lib/handlers.py index 817ff260..73070e1d 100644 --- a/paradox/lib/handlers.py +++ b/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) diff --git a/paradox/lib/utils.py b/paradox/lib/utils.py index 1e23114c..9ff51cd0 100644 --- a/paradox/lib/utils.py +++ b/paradox/lib/utils.py @@ -1,4 +1,5 @@ import asyncio +import binascii from collections.abc import Hashable from copy import deepcopy import functools @@ -140,3 +141,92 @@ def __repr__(self): def __get__(self, obj, objtype): """Support instance methods.""" return functools.partial(self.__call__, obj) + + +def mask_secret(value: typing.Any, keep: int = 4) -> str: + """Mask a sensitive identifier, keeping only the last ``keep`` characters.""" + if value is None: + return "****" + + if isinstance(value, (bytes, bytearray)): + value = binascii.hexlify(bytes(value)).decode("utf-8") + else: + value = str(value) + + if keep <= 0 or len(value) <= keep: + return "****" + + return "****" + value[-keep:] + + +def mask_email(value: typing.Any) -> str: + """Render an email address as ``j****@e****.com``.""" + if not value: + return "****" + + local, sep, domain = str(value).partition("@") + if not sep or not local or "." not in domain: + return "****" + + name, _, tld = domain.rpartition(".") + if not name: + return "****" + + return f"{local[0]}****@{name[0]}****.{tld}" + + +def format_duration(seconds: typing.Optional[float]) -> str: + """Render a duration coarsely, using at most the two largest units.""" + if seconds is None: + return "unknown" + + total = int(max(0, seconds)) + days, rem = divmod(total, 86400) + hours, rem = divmod(rem, 3600) + minutes, secs = divmod(rem, 60) + + if days: + parts = [("d", days), ("h", hours)] + elif hours: + parts = [("h", hours), ("m", minutes)] + elif minutes: + parts = [("m", minutes), ("s", secs)] + else: + return f"{secs}s" + + return " ".join(f"{v}{u}" for u, v in parts if v) + + +def describe_connection(config=None) -> str: + """Render the configured connection as a short, redacted descriptor. + + Reads configuration only, so it is safe to call before connecting and + after a connection has dropped. + """ + if config is None: + from paradox.config import config as cfg + + config = cfg + + connection_type = config.CONNECTION_TYPE + + if connection_type == "Serial": + return f"Serial({config.SERIAL_PORT}@{config.SERIAL_BAUD})" + + if connection_type == "PRT3": + return f"PRT3({config.PRT3_SERIAL_PORT}@{config.PRT3_SERIAL_BAUD})" + + if connection_type == "IP": + if config.IP_CONNECTION_BARE: + return "IP-bare({}:{})".format( + config.IP_CONNECTION_HOST, config.IP_CONNECTION_PORT + ) + if config.IP_CONNECTION_SITEID and config.IP_CONNECTION_EMAIL: + return "SITE({} / {}, serial {})".format( + config.IP_CONNECTION_SITEID, + mask_email(config.IP_CONNECTION_EMAIL), + mask_secret(config.IP_CONNECTION_PANEL_SERIAL), + ) + return f"IP({config.IP_CONNECTION_HOST}:{config.IP_CONNECTION_PORT})" + + return f"Unknown({connection_type})" diff --git a/paradox/main.py b/paradox/main.py index df9fa2b3..25ee0b9d 100755 --- a/paradox/main.py +++ b/paradox/main.py @@ -1,6 +1,7 @@ import asyncio import logging from logging.handlers import RotatingFileHandler +import platform import signal import sys import time @@ -10,6 +11,7 @@ from paradox.exceptions import PAICriticalException from paradox.interfaces.interface_manager import InterfaceManager from paradox.lib.encodings import register_encodings +from paradox.lib.utils import describe_connection, format_duration from paradox.paradox import Paradox logger = logging.getLogger("PAI") @@ -54,6 +56,19 @@ async def _run(alarm: Paradox): interface_manager = InterfaceManager(alarm, config=cfg) interface_manager.start() + logger.info("=" * 56) + logger.info(" PAI %s", VERSION) + logger.info(" Python %s on %s", platform.python_version(), platform.platform()) + logger.info(" Connection: %s", describe_connection()) + logger.info( + " Interfaces: %s", + ", ".join( + getattr(i, "name", type(i).__name__) for i in interface_manager.interfaces + ) + or "none", + ) + logger.info("=" * 56) + async def exit_handler(signame=None): nonlocal alarm, interface_manager @@ -78,6 +93,32 @@ async def exit_handler(signame=None): ) retry = 1 + connected_since = None + disconnected_at = None + + def mark_connected(): + nonlocal connected_since, disconnected_at + if disconnected_at is not None: + logger.warning( + "Connection recovered after %s down", + format_duration(time.monotonic() - disconnected_at), + ) + connected_since = time.monotonic() + disconnected_at = None + + def mark_disconnected(): + nonlocal connected_since, disconnected_at + if connected_since is None: + # Never reached a healthy session, so there is no uptime to report + # and nothing to "recover" from on the next successful attempt. + return + logger.warning( + "Panel connection ended after %s up", + format_duration(time.monotonic() - connected_since), + ) + connected_since = None + disconnected_at = time.monotonic() + while alarm is not None: logger.info("Starting...") retry_time_wait = 2 ^ retry @@ -86,24 +127,35 @@ async def exit_handler(signame=None): try: if await alarm.full_connect(): retry = 1 + mark_connected() await alarm.loop() else: - logger.error("Unable to connect to alarm") + logger.error("Unable to connect to alarm via %s", describe_connection()) + mark_disconnected() if alarm: await asyncio.sleep(retry_time_wait) except ConnectionError as e: # Connection to IP Module or MQTT lost - logger.error("Connection to panel lost: %s. Restarting" % str(e)) + mark_disconnected() + logger.error( + "Connection to panel lost via %s: %s. Restarting", + describe_connection(), + e, + ) await asyncio.sleep(retry_time_wait) except OSError: # Connection to IP Module or MQTT lost + mark_disconnected() logger.exception("Restarting") await asyncio.sleep(retry_time_wait) except PAICriticalException: + mark_disconnected() logger.exception("PAI Critical exception. Stopping PAI") break except (KeyboardInterrupt, SystemExit): + mark_disconnected() break # break exits the retry loop except Exception: + mark_disconnected() logger.exception("Restarting") await asyncio.sleep(retry_time_wait) diff --git a/paradox/paradox.py b/paradox/paradox.py index ddf83d00..871366bb 100644 --- a/paradox/paradox.py +++ b/paradox/paradox.py @@ -26,7 +26,7 @@ from paradox.lib import ps from paradox.lib.async_message_manager import ErrorMessageHandler, EventMessageHandler from paradox.lib.handlers import PersistentHandler -from paradox.lib.utils import deep_merge, sanitize_key +from paradox.lib.utils import deep_merge, describe_connection, sanitize_key from paradox.parsers.status import convert_raw_status logger = logging.getLogger("PAI").getChild(__name__) @@ -210,7 +210,10 @@ async def _prt3_connect(self) -> bool: ), ) self.run_state = RunState.CONNECTED - logger.info("PRT3 connection OK") + logger.info( + "Connected via %s to PRT3 (no panel identification)", + describe_connection(), + ) return True except asyncio.TimeoutError: logger.error("Timeout waiting for PRT3 COMM&ok") @@ -232,7 +235,7 @@ async def connect(self) -> bool: logger.info("Connecting to interface") if not await self.connection.connect(): self.run_state = RunState.ERROR - logger.error("Failed to connect to interface") + logger.error("Failed to connect to interface %s", describe_connection()) return False logger.info("Connecting to Panel") @@ -265,7 +268,12 @@ async def connect(self) -> bool: initiate_reply.fields.value.serial_number ).decode() - logger.info(f"Panel Identified {model} version {firmware_version}") + logger.info( + "Connected via %s to %s version %s", + describe_connection(), + model, + firmware_version, + ) else: raise ConnectionError("Panel did not replied to InitiateCommunication") @@ -556,7 +564,7 @@ async def control_zone(self, zone: str, command: str) -> bool: # Not Found if len(zones_selected) == 0: - logger.error("No zones selected") + logger.warning("No zones selected") return False # Apply state changes @@ -564,9 +572,9 @@ async def control_zone(self, zone: str, command: str) -> bool: try: accepted = await self.panel.control_zones(zones_selected, command) except NotImplementedError: - logger.error("control_zone is not implemented for this alarm type") + logger.warning("control_zone is not implemented for this alarm type") except asyncio.CancelledError: - logger.error("control_zone canceled") + logger.debug("control_zone canceled") except asyncio.TimeoutError: logger.error("control_zone timeout") @@ -583,7 +591,7 @@ async def control_partition(self, partition: str, command: str) -> bool: # Not Found if len(partitions_selected) == 0: - logger.error("No partitions selected") + logger.warning("No partitions selected") return False # Apply state changes @@ -591,9 +599,9 @@ async def control_partition(self, partition: str, command: str) -> bool: try: accepted = await self.panel.control_partitions(partitions_selected, command) except NotImplementedError: - logger.error("control_partition is not implemented for this alarm type") + logger.warning("control_partition is not implemented for this alarm type") except asyncio.CancelledError: - logger.error("control_partition canceled") + logger.debug("control_partition canceled") except asyncio.TimeoutError: logger.error("control_partition timeout") @@ -636,20 +644,20 @@ async def control_utility_key(self, key: int) -> bool: :returns: True if the panel accepted the command, False otherwise. """ if cfg.CONNECTION_TYPE != "PRT3": - logger.error( + logger.warning( "control_utility_key is only supported with CONNECTION_TYPE = 'PRT3'" ) return False try: return await self.panel.send_utility_key(key) except NotImplementedError: - logger.error("send_utility_key not implemented for this panel type") + logger.warning("send_utility_key not implemented for this panel type") return False except (ValueError, TypeError) as e: - logger.error("control_utility_key: invalid key %r — %s", key, e) + logger.warning("control_utility_key: invalid key %r — %s", key, e) return False except asyncio.CancelledError: - logger.error("control_utility_key canceled") + logger.debug("control_utility_key canceled") raise def _init_module_pgms(self): @@ -691,9 +699,9 @@ async def control_output(self, output, command) -> bool: try: accepted = await self.panel.control_outputs(outputs_selected, command) except NotImplementedError: - logger.error("control_output is not implemented for this alarm type") + logger.warning("control_output is not implemented for this alarm type") except asyncio.CancelledError: - logger.error("control_output canceled") + logger.debug("control_output canceled") raise except asyncio.TimeoutError: logger.error("control_output timeout") @@ -711,11 +719,11 @@ async def control_output(self, output, command) -> bool: out["module_address"], out["pgm_index"], command ) except NotImplementedError: - logger.error( + logger.warning( "control_module_pgm_outputs is not implemented for this alarm type" ) except asyncio.CancelledError: - logger.error("control_module_pgm_output canceled") + logger.debug("control_module_pgm_output canceled") raise except asyncio.TimeoutError: logger.error("control_output timeout") @@ -726,7 +734,7 @@ async def control_output(self, output, command) -> bool: ) return accepted - logger.error("No outputs selected") + logger.warning("No outputs selected") return False async def send_panic(self, partition_id, panic_type, user_id) -> bool: @@ -741,15 +749,16 @@ async def send_panic(self, partition_id, panic_type, user_id) -> bool: if partition is None or user is None: logger.error("Send panic: user or partition is not found") + return False try: return await self.panel.send_panic( [partition["id"]], panic_type, user["id"] ) except NotImplementedError: - logger.error("send_panic is not implemented for this alarm type") + logger.warning("send_panic is not implemented for this alarm type") except asyncio.CancelledError: - logger.error("send_panic canceled") + logger.debug("send_panic canceled") except asyncio.TimeoutError: logger.error("send_panic timeout") @@ -763,7 +772,7 @@ async def control_door(self, door, command) -> bool: # Not Found if len(doors_selected) == 0: - logger.error("No doors selected") + logger.warning("No doors selected") return False # Apply state changes @@ -771,9 +780,9 @@ async def control_door(self, door, command) -> bool: try: accepted = await self.panel.control_doors(doors_selected, command) except NotImplementedError: - logger.error("control_door is not implemented for this alarm type") + logger.warning("control_door is not implemented for this alarm type") except asyncio.CancelledError: - logger.error("control_door canceled") + logger.debug("control_door canceled") except asyncio.TimeoutError: logger.error("control_door timeout") # Apply state changes diff --git a/tests/connection/ip/test_protocol.py b/tests/connection/ip/test_protocol.py index c674e588..58c9a6fa 100644 --- a/tests/connection/ip/test_protocol.py +++ b/tests/connection/ip/test_protocol.py @@ -112,7 +112,7 @@ async def test_unknown_message_type_is_logged(protocol, handler, caplog): protocol.data_received(build(b"\x01", IPMessageType.ip_request)) handler.on_message.assert_not_called() handler.on_ip_message.assert_not_called() - assert [r for r in caplog.records if r.levelname == "ERROR"] + assert [r for r in caplog.records if r.levelname == "WARNING"] async def test_raw_dump_logging_does_not_raise(protocol, mocker): diff --git a/tests/connection/ip/test_stun_redaction.py b/tests/connection/ip/test_stun_redaction.py new file mode 100644 index 00000000..448ebf26 --- /dev/null +++ b/tests/connection/ip/test_stun_redaction.py @@ -0,0 +1,39 @@ +from paradox.connections.ip.stun_session import redact_site_info + +SITE_INFO = { + "site": [ + { + "email": "john@example.com", + "module": [ + {"panelSerial": "7106152c", "xoraddr": "abcd"}, + {"panelSerial": "deadbeef", "xoraddr": None}, + ], + } + ] +} + + +def test_redact_site_info_masks_serials_and_email(): + result = redact_site_info(SITE_INFO) + + modules = result["site"][0]["module"] + assert modules[0]["panelSerial"] == "****152c" + assert modules[1]["panelSerial"] == "****beef" + assert result["site"][0]["email"] == "j****@e****.com" + + +def test_redact_site_info_preserves_other_fields_and_does_not_mutate(): + result = redact_site_info(SITE_INFO) + + assert result["site"][0]["module"][0]["xoraddr"] == "abcd" + assert SITE_INFO["site"][0]["module"][0]["panelSerial"] == "7106152c" + + +def test_redact_site_info_output_contains_no_raw_secrets(): + import json + + dumped = json.dumps(redact_site_info(SITE_INFO)) + + assert "7106152c" not in dumped + assert "deadbeef" not in dumped + assert "john@example.com" not in dumped diff --git a/tests/lib/test_handlers_level.py b/tests/lib/test_handlers_level.py new file mode 100644 index 00000000..c8d420c4 --- /dev/null +++ b/tests/lib/test_handlers_level.py @@ -0,0 +1,14 @@ +import logging + +from paradox.lib.handlers import HandlerRegistry + + +async def test_no_handler_logs_warning_not_error(caplog): + registry = HandlerRegistry() + + with caplog.at_level(logging.WARNING, logger="PAI"): + await registry.handle("some unhandled message") + + records = [r for r in caplog.records if "No handler for message" in r.message] + assert len(records) == 1 + assert records[0].levelno == logging.WARNING diff --git a/tests/lib/test_utils.py b/tests/lib/test_utils.py index cc19e7a0..aca99211 100644 --- a/tests/lib/test_utils.py +++ b/tests/lib/test_utils.py @@ -1,8 +1,18 @@ import json from construct import Container, ListContainer +import pytest -from paradox.lib.utils import construct_free, deep_merge, sanitize_key, SerializableToJSONEncoder +from paradox.lib.utils import ( + SerializableToJSONEncoder, + construct_free, + deep_merge, + describe_connection, + format_duration, + mask_email, + mask_secret, + sanitize_key, +) def test_deep_merge(): @@ -73,4 +83,124 @@ def serialize(self): data = {1: TestEntity()} - assert '{"1": {"a": "b"}}' == json.dumps(data, cls=SerializableToJSONEncoder) \ No newline at end of file + assert '{"1": {"a": "b"}}' == json.dumps(data, cls=SerializableToJSONEncoder) + + +@pytest.mark.parametrize( + "value,expected", + [ + ("7106152c", "****152c"), + (b"\x71\x06\x15\x2c", "****152c"), + ("abc", "****"), + ("", "****"), + (None, "****"), + (1234567, "****4567"), + ], +) +def test_mask_secret(value, expected): + assert mask_secret(value) == expected + + +def test_mask_secret_keep_zero(): + assert mask_secret("7106152c", keep=0) == "****" + + +@pytest.mark.parametrize( + "value,expected", + [ + ("john@example.com", "j****@e****.com"), + ("a@b.io", "a****@b****.io"), + ("notanemail", "****"), + ("", "****"), + (None, "****"), + ], +) +def test_mask_email(value, expected): + assert mask_email(value) == expected + + +@pytest.mark.parametrize( + "seconds,expected", + [ + (None, "unknown"), + (0, "0s"), + (0.4, "0s"), + (45, "45s"), + (60, "1m"), + (723, "12m 3s"), + (3600, "1h"), + (8040, "2h 14m"), + (315000, "3d 15h"), + ], +) +def test_format_duration(seconds, expected): + assert format_duration(seconds) == expected + + +class _Cfg: + def __init__(self, **kwargs): + self.CONNECTION_TYPE = "IP" + self.SERIAL_PORT = "/dev/ttyS1" + self.SERIAL_BAUD = 9600 + self.PRT3_SERIAL_PORT = "/dev/ttyUSB0" + self.PRT3_SERIAL_BAUD = 57600 + self.IP_CONNECTION_HOST = "192.168.1.10" + self.IP_CONNECTION_PORT = 10000 + self.IP_CONNECTION_BARE = False + self.IP_CONNECTION_SITEID = None + self.IP_CONNECTION_EMAIL = None + self.IP_CONNECTION_PANEL_SERIAL = None + self.__dict__.update(kwargs) + + +def test_describe_connection_serial(): + assert ( + describe_connection(_Cfg(CONNECTION_TYPE="Serial")) == "Serial(/dev/ttyS1@9600)" + ) + + +def test_describe_connection_prt3(): + assert ( + describe_connection(_Cfg(CONNECTION_TYPE="PRT3")) == "PRT3(/dev/ttyUSB0@57600)" + ) + + +def test_describe_connection_local_ip(): + assert describe_connection(_Cfg()) == "IP(192.168.1.10:10000)" + + +def test_describe_connection_bare_ip(): + assert ( + describe_connection(_Cfg(IP_CONNECTION_BARE=True)) + == "IP-bare(192.168.1.10:10000)" + ) + + +def test_describe_connection_site_masks_secrets(): + cfg = _Cfg( + IP_CONNECTION_SITEID="MySite", + IP_CONNECTION_EMAIL="john@example.com", + IP_CONNECTION_PANEL_SERIAL="7106152c", + ) + result = describe_connection(cfg) + + assert result == "SITE(MySite / j****@e****.com, serial ****152c)" + assert "john@example.com" not in result + assert "7106152c" not in result + + +def test_describe_connection_unknown(): + assert ( + describe_connection(_Cfg(CONNECTION_TYPE="Carrier Pigeon")) + == "Unknown(Carrier Pigeon)" + ) + + +def test_describe_connection_site_requires_both_id_and_email(): + """Only one of SITEID/EMAIL set must fall back to the local IP rendering.""" + assert describe_connection(_Cfg(IP_CONNECTION_SITEID="MySite")) == ( + "IP(192.168.1.10:10000)" + ) + assert describe_connection(_Cfg(IP_CONNECTION_EMAIL="john@example.com")) == ( + "IP(192.168.1.10:10000)" + ) diff --git a/tests/test_main_uptime.py b/tests/test_main_uptime.py new file mode 100644 index 00000000..972fd8fd --- /dev/null +++ b/tests/test_main_uptime.py @@ -0,0 +1,80 @@ +import logging +from unittest.mock import MagicMock, patch + +import pytest + +from paradox import main as pai_main + + +class FakeAlarm: + """Drives _run() through a scripted sequence of connect outcomes.""" + + def __init__(self, script): + self._script = list(script) + self.attempts = 0 + + async def full_connect(self): + self.attempts += 1 + return self._script[self.attempts - 1] != "fail" + + async def loop(self): + if self._script[self.attempts - 1] == "stop": + raise KeyboardInterrupt + + async def disconnect(self): + pass + + +async def _nosleep(*args, **kwargs): + return None + + +async def run_scripted(script, caplog): + alarm = FakeAlarm(script) + interface_manager = MagicMock() + interface_manager.interfaces = [] + + clock = [1000.0] + + def monotonic(): + clock[0] += 100 + return clock[0] + + with patch.object( + pai_main, "InterfaceManager", return_value=interface_manager + ), patch.object(pai_main.asyncio, "sleep", new=_nosleep), patch.object( + pai_main.time, "monotonic", monotonic + ): + with caplog.at_level(logging.DEBUG, logger="PAI"): + await pai_main._run(alarm) + + return [r.message for r in caplog.records] + + +@pytest.mark.parametrize("failures", [1, 3]) +async def test_cold_start_failures_do_not_log_a_recovery(failures, caplog): + """A first-ever connect must never claim to have "recovered".""" + messages = await run_scripted(["fail"] * failures + ["stop"], caplog) + + assert [m for m in messages if "Unable to connect to alarm" in m] + assert not [m for m in messages if "Connection recovered" in m] + + +async def test_recovery_is_logged_after_a_real_session_drops(caplog): + messages = await run_scripted(["ok", "fail", "stop"], caplog) + + assert [m for m in messages if "Panel connection ended after" in m] + assert [m for m in messages if "Connection recovered after" in m] + + +async def test_first_successful_connect_logs_no_recovery(caplog): + messages = await run_scripted(["stop"], caplog) + + assert not [m for m in messages if "Connection recovered" in m] + + +async def test_banner_reports_version_and_connection(caplog): + messages = await run_scripted(["stop"], caplog) + + assert any("PAI " in m for m in messages) + assert any("Connection:" in m for m in messages)