From 34d59b38d0cc50a1d6b84f42007f5b126cf02588 Mon Sep 17 00:00:00 2001 From: Jevgeni Kiski Date: Fri, 14 Aug 2026 17:13:20 +0300 Subject: [PATCH 1/2] fix(log): redact serials, add connection context, demote non-fault errors Three problems made production logs hard to use for triage: - The IP module and panel serial numbers were printed verbatim, and logs are routinely pasted into GitHub issues. - The connection method appeared once at startup, often thousands of lines before the failure being reported. - Benign, recoverable and bad-input conditions were logged at ERROR, making an ERROR-only log unusable and training users to ignore it. Redaction: add mask_secret() and mask_email() and apply them to the IP module serial and the STUN site listing's panel serial. Context: add describe_connection(), which renders the configured connection as a short redacted descriptor from config alone, so it is safe to call before connecting and after a drop. Log a startup banner (version, Python, platform, connection, interfaces) and include the descriptor in the connect-failure and connection-lost messages. Levels: demote 31 sites to WARNING (unhandled broadcasts, unsupported commands, bad MQTT input, PRT3 config errors, recoverable framing noise, MQTT broker drops) and 7 `control_* canceled` sites to DEBUG, since those fire on CancelledError during shutdown and are never actionable. Message text is unchanged; only the level moves. Genuine faults (timeouts, login failures, connection loss, every logger.exception) stay at ERROR. Uptime: track connect/disconnect timestamps in the retry loop with time.monotonic() and log "Panel connection ended after X up" and "Connection recovered after X down", so stability is greppable from an ERROR/WARNING-level log. Also drops an unused paho import and a redundant getattr in mqtt/core.py, which the flake8 hook flags on any commit touching that file. --- .gitignore | 3 + paradox/connections/ip/commands.py | 14 +-- paradox/connections/ip/protocol.py | 2 +- paradox/connections/ip/stun_session.py | 4 +- paradox/hardware/evo/panel.py | 18 ++-- paradox/hardware/panel.py | 2 +- paradox/hardware/prt3/panel.py | 10 +- paradox/interfaces/mqtt/basic.py | 8 +- paradox/interfaces/mqtt/core.py | 40 ++++++-- paradox/lib/handlers.py | 2 +- paradox/lib/utils.py | 90 ++++++++++++++++++ paradox/main.py | 52 ++++++++++- paradox/paradox.py | 58 +++++++----- tests/connection/ip/test_protocol.py | 2 +- tests/lib/test_handlers_level.py | 14 +++ tests/lib/test_utils.py | 124 ++++++++++++++++++++++++- 16 files changed, 378 insertions(+), 65 deletions(-) create mode 100644 tests/lib/test_handlers_level.py 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/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..63533eb2 100644 --- a/paradox/connections/ip/stun_session.py +++ b/paradox/connections/ip/stun_session.py @@ -8,6 +8,7 @@ from paradox.exceptions import ConnectToSiteFailed, StunSessionRefreshFailed from paradox.lib import stun +from paradox.lib.utils import mask_secret logger = logging.getLogger("PAI").getChild(__name__) @@ -102,7 +103,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..88096ec4 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,30 @@ 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.info( + "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 not None: + logger.warning( + "Panel connection ended after %s up", + format_duration(time.monotonic() - connected_since), + ) + connected_since = None + if disconnected_at is None: + disconnected_at = time.monotonic() + while alarm is not None: logger.info("Starting...") retry_time_wait = 2 ^ retry @@ -86,16 +125,24 @@ 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: @@ -104,6 +151,7 @@ async def exit_handler(signame=None): except (KeyboardInterrupt, SystemExit): 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..a72060c9 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: @@ -740,16 +748,16 @@ async def send_panic(self, partition_id, panic_type, user_id) -> bool: user = self.storage.get_container_object("user", user_id) if partition is None or user is None: - logger.error("Send panic: user or partition is not found") + logger.warning("Send panic: user or partition is not found") 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 +771,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 +779,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/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..427521e5 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,114 @@ 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)" + ) From e242cb10800d920a325dac18c3a073c808d30eef Mon Sep 17 00:00:00 2001 From: Jevgeni Kiski Date: Fri, 14 Aug 2026 17:36:57 +0300 Subject: [PATCH 2/2] fix(log): address review findings on redaction and uptime accounting - Cold start no longer claims a false recovery. mark_disconnected() now returns early when no healthy session was ever established, so a run that fails its first N connect attempts does not log "Connection recovered after X down" on the first success. Covered by a test that fails against the previous logic. - "Send panic: user or partition is not found" goes back to ERROR. A panic command silently failing is operationally serious and should reach anyone alerting on ERROR. Also adds the missing `return False` on that branch: control flow previously fell through to `partition["id"]` and raised TypeError on None. - Redacts the SWAN site listing. The full site_info blob was dumped to DEBUG as raw JSON, leaking every module's panelSerial and the account email four lines before the point where panelSerial was masked. - Records session uptime when the loop exits via PAICriticalException, KeyboardInterrupt or SystemExit, which previously lost the uptime of a session ending in a critical fault. - Raises the two uptime messages and the LOGGING_LEVEL_FILE default to WARNING. The default was ERROR, so the uptime signal this feature adds would have been invisible in exactly the file logs users paste into issue reports. The demotions in the previous commit lower the noise floor enough that WARNING is now a quiet level. Adds tests for the cold-start case, the connect/drop/recover cycle, the site-info redaction, and the SITEID-without-EMAIL fallback. --- paradox/config.py | 2 +- paradox/connections/ip/stun_session.py | 27 +++++++- paradox/main.py | 22 +++--- paradox/paradox.py | 3 +- tests/connection/ip/test_stun_redaction.py | 39 +++++++++++ tests/lib/test_utils.py | 10 +++ tests/test_main_uptime.py | 80 ++++++++++++++++++++++ 7 files changed, 170 insertions(+), 13 deletions(-) create mode 100644 tests/connection/ip/test_stun_redaction.py create mode 100644 tests/test_main_uptime.py 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/stun_session.py b/paradox/connections/ip/stun_session.py index 63533eb2..4c6a00ed 100644 --- a/paradox/connections/ip/stun_session.py +++ b/paradox/connections/ip/stun_session.py @@ -8,10 +8,31 @@ from paradox.exceptions import ConnectToSiteFailed, StunSessionRefreshFailed from paradox.lib import stun -from paradox.lib.utils import mask_secret +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): @@ -37,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: diff --git a/paradox/main.py b/paradox/main.py index 88096ec4..25ee0b9d 100755 --- a/paradox/main.py +++ b/paradox/main.py @@ -99,7 +99,7 @@ async def exit_handler(signame=None): def mark_connected(): nonlocal connected_since, disconnected_at if disconnected_at is not None: - logger.info( + logger.warning( "Connection recovered after %s down", format_duration(time.monotonic() - disconnected_at), ) @@ -108,14 +108,16 @@ def mark_connected(): def mark_disconnected(): nonlocal connected_since, disconnected_at - if connected_since is not None: - logger.warning( - "Panel connection ended after %s up", - format_duration(time.monotonic() - connected_since), - ) - connected_since = None - if disconnected_at is None: - disconnected_at = time.monotonic() + 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...") @@ -146,9 +148,11 @@ def 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() diff --git a/paradox/paradox.py b/paradox/paradox.py index a72060c9..871366bb 100644 --- a/paradox/paradox.py +++ b/paradox/paradox.py @@ -748,7 +748,8 @@ async def send_panic(self, partition_id, panic_type, user_id) -> bool: user = self.storage.get_container_object("user", user_id) if partition is None or user is None: - logger.warning("Send panic: user or partition is not found") + logger.error("Send panic: user or partition is not found") + return False try: return await self.panel.send_panic( 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_utils.py b/tests/lib/test_utils.py index 427521e5..aca99211 100644 --- a/tests/lib/test_utils.py +++ b/tests/lib/test_utils.py @@ -194,3 +194,13 @@ def test_describe_connection_unknown(): 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)