From 94a93bbf310256f9830d2a1481c07c1b995d5887 Mon Sep 17 00:00:00 2001 From: j5lien <1511405+j5lien@users.noreply.github.com> Date: Tue, 29 Sep 2026 16:59:19 +0200 Subject: [PATCH] Release 2.1.0: structured logs - Every log record names its kind in an `event` field (packet_received, teach_in, base_id_received, serial_error, data_crc_error, unknown_profile...) and carries its context as fields: base ID, transport/port/host/client, the serial error (lost until now), length or bytes of a dropped packet, EEP and command of an unknown profile - packet_log_fields() matches Packet.to_dict(): packet_type and rorg are enum names instead of integers, plus destination, status, repeater_count and eep - The events are listed in the monitoring guide - Version 2.1.0; install instructions (README, docs) point at the 2.1.0 tag Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 25 ++++++ CLAUDE.md | 6 +- README.md | 9 ++- TODO.md | 1 + docs/getting-started.md | 6 +- docs/guides/monitoring.md | 28 ++++++- docs/index.md | 2 +- enocean/communicators/communicator.py | 49 ++++++++---- enocean/communicators/serialcommunicator.py | 26 ++++-- enocean/communicators/tcpcommunicator.py | 28 +++++-- .../tests/test_serial_communicator.py | 19 ++++- .../tests/test_tcp_communicator.py | 8 +- enocean/protocol/eep.py | 21 +++-- enocean/protocol/packet.py | 16 +++- enocean/tests/test_logging.py | 79 +++++++++++++++++-- pyproject.toml | 2 +- uv.lock | 2 +- 17 files changed, 269 insertions(+), 58 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b43ffe8..a7d8a3b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,30 @@ All notable changes to this project are documented here. The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and versions follow [Semantic Versioning](https://semver.org/). +## [2.1.0] - 2026-09-29 + +Structured logs: every record names its kind in an `event` field and carries its context, so logs can be filtered and +aggregated without parsing messages (e.g. `event:serial_error` in VictoriaLogs). The events and their fields are listed +in the [monitoring guide](https://j5lien.github.io/enocean/guides/monitoring/#logs). + +### Added + +- `event` field on the library's log records: `packet_received`, `packet_sent`, `teach_in`, `base_id_received`, + `base_id_timeout`, `communicator_started`/`stopped`, `client_connected`/`disconnected`, `serial_error`, + `processing_error`, `header_crc_error`, `data_crc_error`, `malformed_packet`, `unknown_profile`, `unknown_field`... +- Their context as fields: `base_id`; `transport`, `port`, `host` and `client` for the transports; `error` for serial + port errors (also in the message, it was lost); `length` of a corrupted packet; `data` and `optional` (hex) of a + malformed one, to replay it; `eep` and `command` of an unknown profile; `shortcut` of an unknown field; `outcome` of + a teach-in. +- Packet records also carry `destination`, `status`, `repeater_count` and `eep`. +- `SerialCommunicator.port`, the serial port it was opened on. + +### Changed + +- The `packet_type` and `rorg` fields of log records are enum names (`RADIO_ERP1`, `VLD`) instead of integers, as in + `packet.to_dict()`: log queries on their numeric values need updating. +- The communicators' started/stopped messages name the port, and the TCP client messages the client's address. + ## [2.0.2] - 2026-09-29 ### Fixed @@ -148,6 +172,7 @@ First release of the [j5lien/enocean](https://github.com/j5lien/enocean) fork of Last release of [kipe/enocean](https://github.com/kipe/enocean). +[2.1.0]: https://github.com/j5lien/enocean/compare/2.0.2...2.1.0 [2.0.2]: https://github.com/j5lien/enocean/compare/2.0.1...2.0.2 [2.0.1]: https://github.com/j5lien/enocean/compare/2.0.0...2.0.1 [2.0.0]: https://github.com/j5lien/enocean/compare/1.0.0...2.0.0 diff --git a/CLAUDE.md b/CLAUDE.md index 145a3f9..b71b2ff 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -101,8 +101,10 @@ The `enocean` logger has a `NullHandler`: the library is silent unless the appli expected radio noise (header CRC errors while resynchronizing), INFO for lifecycle events (started/stopped, base ID, teach-in answered), WARNING for dropped or unusable data (data CRC error, malformed packet, unknown profile), ERROR for transport failures, `logger.exception` for errors raised while processing packets (e.g. in user callbacks). Pass -lazy `%s` args, never pre-formatted strings, and `extra=packet_log_fields(packet)` on packet-related records so -structured handlers get `packet_type`/`rorg`/`sender`/`dbm`. +lazy `%s` args, never pre-formatted strings. Every record gets an `event` field (snake_case, e.g. `base_id_received`) +plus its context as structured fields, through `extra=`; packet-related records use +`extra=packet_log_fields(packet, event)`, whose names and formats match `Packet.to_dict()`. The events are listed in +`docs/guides/monitoring.md`: update it with new ones. ## Documentation diff --git a/README.md b/README.md index 64cd96d..7b0090b 100644 --- a/README.md +++ b/README.md @@ -19,9 +19,9 @@ This is a maintained fork of [kipe/enocean](https://github.com/kipe/enocean), wh Requires Python 3.10 or later. ```bash -pip install git+https://github.com/j5lien/enocean.git@2.0.2 +pip install git+https://github.com/j5lien/enocean.git@2.1.0 # or, in a uv-managed project -uv add git+https://github.com/j5lien/enocean.git --tag 2.0.2 +uv add git+https://github.com/j5lien/enocean.git --tag 2.1.0 ``` Wheels are also attached to each [GitHub release](https://github.com/j5lien/enocean/releases); see @@ -132,8 +132,9 @@ More in [`examples/`](examples/). `TCPCommunicator` receives packets over TCP in ## Monitoring **Logs.** The library is silent until you configure logging. `enocean.consolelogger.init_logging()` sends its logs to -stderr, or as one JSON object per line with `init_logging(json_format=True)`; packet-related records carry -`packet_type`, `rorg`, `sender` and `dbm` fields. +stderr, or as one JSON object per line with `init_logging(json_format=True)`; records carry an `event` field +(`packet_received`, `teach_in`, `serial_error`...) and structured fields such as `sender`, `rorg`, `eep` or `dbm`, named +as in `packet.to_dict()` (see the [monitoring guide](https://j5lien.github.io/enocean/guides/monitoring/#logs)). **Statistics and health**, always available, no dependency: diff --git a/TODO.md b/TODO.md index 143695c..a74de53 100644 --- a/TODO.md +++ b/TODO.md @@ -143,3 +143,4 @@ aujourd'hui) ; on **s'aligne sur les noms officiels** des champs (version 2.0). - [x] Release 2.0.0 : profils officiels, API d'intégration, supervision, documentation - [x] Release 2.0.1 : `status` et `repeater_count` des télégrammes VLD (lus dans le niveau de sécurité) - [x] Release 2.0.2 : `dbm` à `None` au lieu de -255 pour les télégrammes à envoyer +- [x] Release 2.1.0 : logs structurés (champ `event` et contexte sur chaque log, champs de paquet alignés sur `to_dict()`) diff --git a/docs/getting-started.md b/docs/getting-started.md index 489780b..de6ea8a 100644 --- a/docs/getting-started.md +++ b/docs/getting-started.md @@ -3,11 +3,11 @@ ## Installation ```bash -pip install git+https://github.com/j5lien/enocean.git@2.0.2 +pip install git+https://github.com/j5lien/enocean.git@2.1.0 # or, in a uv-managed project -uv add git+https://github.com/j5lien/enocean.git --tag 2.0.2 +uv add git+https://github.com/j5lien/enocean.git --tag 2.1.0 # with Prometheus metrics -pip install "enocean[prometheus] @ git+https://github.com/j5lien/enocean.git@2.0.2" +pip install "enocean[prometheus] @ git+https://github.com/j5lien/enocean.git@2.1.0" ``` ## Finding the module's serial port diff --git a/docs/guides/monitoring.md b/docs/guides/monitoring.md index b271e8e..4003b6a 100644 --- a/docs/guides/monitoring.md +++ b/docs/guides/monitoring.md @@ -14,8 +14,32 @@ init_logging(level=logging.INFO, json_format=True) ``` Levels: DEBUG for per-packet traffic and expected radio noise, INFO for lifecycle events (started, base ID, teach-in -answered), WARNING for dropped data (corrupted telegram, unknown profile), ERROR for transport failures. Packet-related -records carry `packet_type`, `rorg`, `sender` and `dbm` fields. +answered), WARNING for dropped data (corrupted telegram, unknown profile), ERROR for transport failures. + +Records carry structured fields, emitted by the JSON format (and available on the `LogRecord` to any handler). Every +record (but a few DEBUG traces) has an `event` field naming its kind, to filter on it: + +| `event` | Level | Other fields | +| --- | --- | --- | +| `packet_received`, `packet_sent` | DEBUG | the packet's fields (below) | +| `teach_in` | INFO | the packet's fields, `outcome` (`accepted`, `deleted`, `profile not supported`) | +| `base_id_received` | INFO | `base_id` (`FF:87:CA:00`) | +| `base_id_timeout` | WARNING | | +| `communicator_started`, `communicator_stopped` | INFO | `transport` (`serial`, `tcp`), `port`, `host` (TCP) | +| `client_connected`, `client_disconnected` | DEBUG | `transport`, `host`, `port`, `client` (`192.168.1.10:51234`) | +| `serial_error` | ERROR | `transport`, `port`, `error` | +| `processing_error` | ERROR | the traceback (e.g. of an exception raised by the callback) | +| `header_crc_error` | DEBUG | | +| `data_crc_error` | WARNING | `packet_type`, `length` | +| `malformed_packet` | WARNING | `packet_type`, `data`, `optional` (hex, to replay it) | +| `unknown_profile` | WARNING | `eep` (`D2-01-12`), `command` | +| `unknown_field` | WARNING | `shortcut` | +| `invalid_packet` | ERROR | (`send()` was given something else than a packet) | +| `profiles_not_loaded` | WARNING | (broken installation) | + +The packet's fields use the names and formats of `packet.to_dict()`: `packet_type` and `rorg` (enum names, e.g. +`RADIO_ERP1`, `VLD`), and for radio telegrams `sender`, `destination`, `dbm` (None for telegrams to send), `status`, +`repeater_count` and `eep` (once decoded, e.g. with a device registry). ## Statistics and health diff --git a/docs/index.md b/docs/index.md index 7c35934..d6ebc11 100644 --- a/docs/index.md +++ b/docs/index.md @@ -14,7 +14,7 @@ actuators…) through an EnOcean USB/serial module (e.g. USB 300) or a TCP bridg It requires Python 3.10 or later, and has one dependency: `pyserial`. ```bash -pip install git+https://github.com/j5lien/enocean.git@2.0.2 +pip install git+https://github.com/j5lien/enocean.git@2.1.0 ``` ```python diff --git a/enocean/communicators/communicator.py b/enocean/communicators/communicator.py index 798aa2a..31baa68 100644 --- a/enocean/communicators/communicator.py +++ b/enocean/communicators/communicator.py @@ -8,19 +8,35 @@ from typing import TypeGuard from enocean.devices import Device, DeviceRegistry -from enocean.protocol.constants import PACKET, PARSE_RESULT, RETURN_CODE -from enocean.protocol.packet import Packet, RadioPacket, ResponsePacket, UTETeachInPacket +from enocean.protocol.constants import PACKET, PARSE_RESULT, RETURN_CODE, RORG +from enocean.protocol.packet import Packet, RadioPacket, ResponsePacket, UTETeachInPacket, enum_name from enocean.stats import CommunicatorStats, Health from enocean.utils import to_hex_string -def packet_log_fields(packet: Packet) -> dict[str, object]: - """Fields attached to log records about a packet, for structured log handlers.""" - fields: dict[str, object] = {'packet_type': int(packet.packet_type)} +def packet_log_fields(packet: Packet, event: str | None = None) -> dict[str, object]: + """Fields attached to log records about a packet, for structured log handlers. + + The same names and formats as Packet.to_dict(): enum names, hex IDs. + + Args: + packet: The packet the record is about. + event: The record's `event` field (e.g. 'packet_received'), to filter records by kind. + """ + fields: dict[str, object] = {'packet_type': enum_name(PACKET, packet.packet_type)} + if event is not None: + fields['event'] = event if isinstance(packet, RadioPacket): - fields['rorg'] = int(packet.rorg) - fields['sender'] = packet.sender_hex - fields['dbm'] = packet.dbm + eep_id = packet.eep_id + fields.update( + rorg=enum_name(RORG, packet.rorg), + sender=packet.sender_hex, + destination=packet.destination_hex, + dbm=packet.dbm, + status=packet.status, + repeater_count=packet.repeater_count, + eep=str(eep_id) if eep_id else None, + ) return fields @@ -80,7 +96,7 @@ def _get_from_send_queue(self) -> Packet | None: """Get message from send queue, if one exists.""" try: packet = self.transmit.get(block=False) - self.logger.debug('Sending %s', packet, extra=packet_log_fields(packet)) + self.logger.debug('Sending %s', packet, extra=packet_log_fields(packet, 'packet_sent')) return packet except queue.Empty: pass @@ -93,7 +109,7 @@ def send(self, packet: Packet) -> bool: False if packet isn't a Packet. """ if not isinstance(packet, Packet): - self.logger.error('Object to send must be an instance of Packet') + self.logger.error('Object to send must be an instance of Packet', extra={'event': 'invalid_packet'}) return False self.transmit.put(packet) return True @@ -128,7 +144,10 @@ def parse(self) -> PARSE_RESULT: if self._base_id_requested and self._is_base_id_response(packet): self._base_id = packet.response_data - self.logger.info('Base ID of the module: %s', to_hex_string(self._base_id)) + base_id = to_hex_string(self._base_id) + self.logger.info( + 'Base ID of the module: %s', base_id, extra={'event': 'base_id_received', 'base_id': base_id} + ) self._base_id_requested = False self.stats.record_base_id_received(time.monotonic() - self._base_id_requested_at) self._base_id_received.set() @@ -139,7 +158,7 @@ def parse(self) -> PARSE_RESULT: if self.base_id is not None: self._answer_pending_teach_ins() - self.logger.debug('Received %s', packet, extra=packet_log_fields(packet)) + self.logger.debug('Received %s', packet, extra=packet_log_fields(packet, 'packet_received')) if self.__callback is None: self.receive.put(packet) else: @@ -167,7 +186,7 @@ def _answer_pending_teach_ins(self) -> None: packet.sender_hex, packet.eep_id, outcome, - extra=packet_log_fields(packet), + extra={**packet_log_fields(packet, 'teach_in'), 'outcome': outcome}, ) self.send(packet.create_response_packet(self._base_id, response)) self.stats.record_teach_in_response() @@ -277,7 +296,9 @@ def base_id(self) -> list[int] | None: self._request_base_id() if threading.current_thread() is not self and not self._base_id_received.wait(1): - self.logger.warning('No response from the module to the Base ID request.') + self.logger.warning( + 'No response from the module to the Base ID request.', extra={'event': 'base_id_timeout'} + ) self.stats.record_base_id_timeout() self._base_id_requested = False # Return the current Base ID (might be None). diff --git a/enocean/communicators/serialcommunicator.py b/enocean/communicators/serialcommunicator.py index 57d376b..6393f05 100644 --- a/enocean/communicators/serialcommunicator.py +++ b/enocean/communicators/serialcommunicator.py @@ -39,13 +39,14 @@ def __init__( serial.SerialException: The port can't be opened. """ super().__init__(callback, teach_in, devices) + self.port = port # Initialize serial port self.__ser = serial.Serial(port, 57600, timeout=0.1) self._transport_ready = True def run(self) -> None: """Thread body: write queued packets, read and parse bytes until stopped or the device disconnects.""" - self.logger.info('SerialCommunicator started') + self.logger.info('SerialCommunicator started on %s', self.port, extra=self._log_fields('communicator_started')) while not self._stop_flag.is_set(): # If there's messages in transmit queue # send them @@ -56,8 +57,12 @@ def run(self) -> None: data = bytearray(packet.build()) try: self.__ser.write(data) - except serial.SerialException: - self.logger.error('Serial port exception while writing! (device disconnected?)') + except serial.SerialException as error: + self.logger.error( + 'Serial port exception while writing! (device disconnected?) %s', + error, + extra={**self._log_fields('serial_error'), 'error': str(error)}, + ) self.stats.record_transport_error() self._transport_ready = False self.stop() @@ -67,8 +72,12 @@ def run(self) -> None: # Read chars from serial port as hex numbers try: self._feed(self.__ser.read(16)) - except serial.SerialException: - self.logger.error('Serial port exception! (device disconnected or multiple access on port?)') + except serial.SerialException as error: + self.logger.error( + 'Serial port exception! (device disconnected or multiple access on port?) %s', + error, + extra={**self._log_fields('serial_error'), 'error': str(error)}, + ) self.stats.record_transport_error() self._transport_ready = False self.stop() @@ -77,11 +86,14 @@ def run(self) -> None: self.parse() except Exception: # Most likely raised by the user's callback: keep running, but with the full traceback - self.logger.exception('Error while processing received packets') + self.logger.exception('Error while processing received packets', extra={'event': 'processing_error'}) self.stats.record_processing_error() time.sleep(0) self.__ser.close() self._transport_ready = False - self.logger.info('SerialCommunicator stopped') + self.logger.info('SerialCommunicator stopped on %s', self.port, extra=self._log_fields('communicator_stopped')) + + def _log_fields(self, event: str) -> dict[str, object]: + return {'event': event, 'transport': 'serial', 'port': self.port} diff --git a/enocean/communicators/tcpcommunicator.py b/enocean/communicators/tcpcommunicator.py index 4dfe8b3..6710ef9 100644 --- a/enocean/communicators/tcpcommunicator.py +++ b/enocean/communicators/tcpcommunicator.py @@ -42,7 +42,9 @@ def __init__( def run(self) -> None: """Thread body: accept clients and parse the bytes they send until stopped.""" - self.logger.info('TCPCommunicator started') + self.logger.info( + 'TCPCommunicator started on %s:%s', self.host, self.port, extra=self._log_fields('communicator_started') + ) sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) sock.bind((self.host, self.port)) sock.listen(5) @@ -54,7 +56,12 @@ def run(self) -> None: (client, addr) = sock.accept() except TimeoutError: continue - self.logger.debug('Client "%s" connected', addr) + client_address = '%s:%s' % addr[:2] + self.logger.debug( + 'Client "%s" connected', + client_address, + extra={**self._log_fields('client_connected'), 'client': client_address}, + ) client.settimeout(0.5) while not self._stop_flag.is_set(): try: @@ -68,10 +75,21 @@ def run(self) -> None: self.parse() except Exception: # Most likely raised by the user's callback: keep serving, but with the full traceback - self.logger.exception('Error while processing received packets') + self.logger.exception( + 'Error while processing received packets', extra={'event': 'processing_error'} + ) self.stats.record_processing_error() client.close() - self.logger.debug('Client disconnected') + self.logger.debug( + 'Client "%s" disconnected', + client_address, + extra={**self._log_fields('client_disconnected'), 'client': client_address}, + ) sock.close() self._transport_ready = False - self.logger.info('TCPCommunicator stopped') + self.logger.info( + 'TCPCommunicator stopped on %s:%s', self.host, self.port, extra=self._log_fields('communicator_stopped') + ) + + def _log_fields(self, event: str) -> dict[str, object]: + return {'event': event, 'transport': 'tcp', 'host': self.host, 'port': self.port} diff --git a/enocean/communicators/tests/test_serial_communicator.py b/enocean/communicators/tests/test_serial_communicator.py index 9761bf2..f7c99c4 100644 --- a/enocean/communicators/tests/test_serial_communicator.py +++ b/enocean/communicators/tests/test_serial_communicator.py @@ -4,6 +4,7 @@ packets (and from send() to bytes on the wire) is exercised. """ +import logging import os import queue import threading @@ -117,7 +118,8 @@ def test_sent_packet_is_written_to_serial(pty_port, running): assert snapshot.bytes_sent == len(packet.build()) -def test_base_id_is_fetched_from_module(pty_port, running): +def test_base_id_is_fetched_from_module(pty_port, running, caplog): + caplog.set_level(logging.INFO, logger='enocean') module, port = pty_port com = running(SerialCommunicator(port=port)) requests = [] @@ -137,9 +139,12 @@ def answer_base_id_request(): assert requests[0].data == [0x08] # CO_RD_IDBASE # The response is also left in the queue for the user assert com.receive.get(timeout=TIMEOUT).packet_type == PACKET.RESPONSE + [record] = [r for r in caplog.records if getattr(r, 'event', None) == 'base_id_received'] + assert record.base_id == 'FF:87:CA:00' -def test_ute_teach_in_is_answered_automatically(pty_port, running): +def test_ute_teach_in_is_answered_automatically(pty_port, running, caplog): + caplog.set_level(logging.INFO, logger='enocean') module, port = pty_port com = SerialCommunicator(port=port) com.base_id = [0xDE, 0xAD, 0xBE, 0xEF] @@ -152,6 +157,8 @@ def test_ute_teach_in_is_answered_automatically(pty_port, running): assert response.rorg == RORG.UTE assert response.sender_hex == 'DE:AD:BE:EF' assert response.destination_hex == '01:94:E3:B9' + [record] = [r for r in caplog.records if getattr(r, 'event', None) == 'teach_in'] + assert (record.sender, record.rorg, record.eep, record.outcome) == ('01:94:E3:B9', 'UTE', 'D2-01-01', 'accepted') def test_ute_teach_in_is_ignored_when_disabled(pty_port, running): @@ -177,7 +184,8 @@ def test_stop_ends_the_thread(pty_port, running): assert not com.is_alive() -def test_device_disconnect_stops_communicator(pty_port, running): +def test_device_disconnect_stops_communicator(pty_port, running, caplog): + caplog.set_level(logging.INFO, logger='enocean') module, port = pty_port com = running(SerialCommunicator(port=port)) time.sleep(0.2) @@ -188,6 +196,11 @@ def test_device_disconnect_stops_communicator(pty_port, running): com.join(TIMEOUT) assert not com.is_alive() assert com.stats.snapshot().transport_errors == 1 + events = {getattr(r, 'event', None): r for r in caplog.records} + assert events['serial_error'].port == port + assert events['serial_error'].error + assert (events['communicator_started'].transport, events['communicator_started'].port) == ('serial', port) + assert events['communicator_stopped'].port == port def test_common_command_packet_roundtrip(pty_port, running): diff --git a/enocean/communicators/tests/test_tcp_communicator.py b/enocean/communicators/tests/test_tcp_communicator.py index 93e7d19..64c962a 100644 --- a/enocean/communicators/tests/test_tcp_communicator.py +++ b/enocean/communicators/tests/test_tcp_communicator.py @@ -3,6 +3,7 @@ clients push ESP3 frames to it over real sockets, as examples/serial_to_tcp.py does. """ +import logging import queue import socket import time @@ -27,16 +28,21 @@ def connect(port): time.sleep(0.02) -def test_frame_from_client_is_received(free_tcp_port, running): +def test_frame_from_client_is_received(free_tcp_port, running, caplog): + caplog.set_level(logging.DEBUG, logger='enocean') com = running(TCPCommunicator(host='127.0.0.1', port=free_tcp_port)) client = connect(free_tcp_port) + client_address = '%s:%s' % client.getsockname() client.sendall(RADIO_FRAME) client.close() packet = com.receive.get(timeout=TIMEOUT) assert isinstance(packet, RadioPacket) assert packet.sender_hex == '01:81:B7:44' + events = {getattr(r, 'event', None): r for r in caplog.records} + assert (events['communicator_started'].transport, events['communicator_started'].port) == ('tcp', free_tcp_port) + assert events['client_connected'].client == client_address def test_multiple_frames_in_one_connection(free_tcp_port, running): diff --git a/enocean/protocol/eep.py b/enocean/protocol/eep.py index 67e432d..a8bc4a2 100644 --- a/enocean/protocol/eep.py +++ b/enocean/protocol/eep.py @@ -167,7 +167,7 @@ def __init__(self) -> None: self.__load_index() except (OSError, ElementTree.ParseError): # The profiles ship with the library: this only happens with a broken installation - self.logger.warning('Cannot load protocol file!') + self.logger.warning('Cannot load protocol file!', extra={'event': 'profiles_not_loaded'}) self.init_ok = False def __load_index(self) -> None: @@ -402,20 +402,25 @@ def find_profile( The variant, None if the profile is unknown. """ if not self.init_ok: - self.logger.warning('EEP profiles not loaded!') + self.logger.warning('EEP profiles not loaded!', extra={'event': 'profiles_not_loaded'}) return None + log_fields = {'event': 'unknown_profile', 'eep': str(EEPId(eep_rorg, rorg_func, rorg_type)), 'command': command} if eep_rorg not in self.telegrams: - self.logger.warning('Cannot find rorg %s in EEP!', hex(eep_rorg)) + self.logger.warning('Cannot find rorg %s in EEP!', hex(eep_rorg), extra=log_fields) return None if rorg_func not in self.telegrams[eep_rorg]: - self.logger.warning('Cannot find rorg %s func %s in EEP!', hex(eep_rorg), hex(rorg_func)) + self.logger.warning('Cannot find rorg %s func %s in EEP!', hex(eep_rorg), hex(rorg_func), extra=log_fields) return None if rorg_type not in self.telegrams[eep_rorg][rorg_func]: self.logger.warning( - 'Cannot find rorg %s func %s type %s in EEP!', hex(eep_rorg), hex(rorg_func), hex(rorg_type) + 'Cannot find rorg %s func %s type %s in EEP!', + hex(eep_rorg), + hex(rorg_func), + hex(rorg_type), + extra=log_fields, ) return None @@ -522,7 +527,11 @@ def set_values( target = next((tag for tag in profile.iter() if tag.get('shortcut') == shortcut), None) if target is None: # TODO: Should we raise an error? - self.logger.warning('Cannot find data description for shortcut %s', shortcut) + self.logger.warning( + 'Cannot find data description for shortcut %s', + shortcut, + extra={'event': 'unknown_field', 'shortcut': shortcut}, + ) continue # update bit_data diff --git a/enocean/protocol/packet.py b/enocean/protocol/packet.py index 22663a1..3cdd407 100644 --- a/enocean/protocol/packet.py +++ b/enocean/protocol/packet.py @@ -175,7 +175,7 @@ def parse_msg( # would otherwise make us wait for, and then drop, bytes belonging to the following valid packets. if buf[5] != crc8.calc(buf[1:5]): # Expected on a noisy line: every stray 0x55 lands here while resynchronizing - Packet.logger.debug('Header CRC error, resynchronizing.') + Packet.logger.debug('Header CRC error, resynchronizing.', extra={'event': 'header_crc_error'}) if on_error: on_error(HEADER_CRC_ERROR) # Skip only the sync byte and resynchronize on the next 0x55 @@ -200,7 +200,7 @@ def parse_msg( 'Data CRC error on a %d byte packet (type 0x%02X), dropping it.', msg_len, packet_type, - extra={'packet_type': packet_type}, + extra={'event': 'data_crc_error', 'packet_type': enum_name(PACKET, packet_type), 'length': msg_len}, ) if on_error: on_error(DATA_CRC_ERROR) @@ -222,7 +222,17 @@ def parse_msg( packet = packet_class(packet_type, data, opt_data) except (IndexError, ValueError): # Valid on the wire, but too short for what its type requires: keep the raw bytes - Packet.logger.warning('Malformed %s packet, returning it unparsed.', packet_class.__name__, exc_info=True) + Packet.logger.warning( + 'Malformed %s packet, returning it unparsed.', + packet_class.__name__, + exc_info=True, + extra={ + 'event': 'malformed_packet', + 'packet_type': enum_name(PACKET, packet_type), + 'data': enocean.utils.to_hex_string(data), + 'optional': enocean.utils.to_hex_string(opt_data), + }, + ) packet = Packet(packet_type, data, opt_data) if on_error: on_error(MALFORMED_PACKET) diff --git a/enocean/tests/test_logging.py b/enocean/tests/test_logging.py index 19420ca..83f54d0 100644 --- a/enocean/tests/test_logging.py +++ b/enocean/tests/test_logging.py @@ -1,8 +1,12 @@ import logging import enocean -from enocean.communicators.communicator import Communicator -from enocean.protocol.packet import Packet +from enocean.communicators.communicator import Communicator, packet_log_fields +from enocean.devices import Device, DeviceRegistry +from enocean.protocol import crc8 +from enocean.protocol.constants import RORG +from enocean.protocol.eep import EEPId +from enocean.protocol.packet import Packet, RadioPacket # A5-02-05 temperature telegram from sender 01:81:B7:44 # fmt: off @@ -43,7 +47,21 @@ def test_corrupted_telegram_is_a_warning(caplog): [warning] = records(caplog, logging.WARNING) assert 'Data CRC error' in warning.getMessage() - assert warning.packet_type == 0x01 + assert warning.event == 'data_crc_error' + assert warning.packet_type == 'RADIO_ERP1' + assert warning.length == len(RADIO_FRAME) + + +def test_malformed_packet_carries_its_bytes(caplog): + caplog.set_level(logging.DEBUG, logger='enocean') + data, optional = [RORG.BS4, 0x01], [0x01] # a 4BS telegram too short for its data and sender + header = [0x00, len(data), len(optional), 0x01] + Packet.parse_msg(bytearray([0x55] + header + [crc8.calc(header)] + data + optional + [crc8.calc(data + optional)])) + + [warning] = records(caplog, logging.WARNING) + assert warning.event == 'malformed_packet' + assert warning.packet_type == 'RADIO_ERP1' + assert (warning.data, warning.optional) == ('A5:01', '01') def test_received_packets_carry_structured_fields(caplog): @@ -54,10 +72,61 @@ def test_received_packets_carry_structured_fields(caplog): com.parse() [received] = [r for r in records(caplog, logging.DEBUG) if r.getMessage().startswith('Received')] + assert received.event == 'packet_received' assert received.sender == '01:81:B7:44' - assert received.rorg == 0xA5 - assert received.packet_type == 0x01 + assert received.destination == 'FF:FF:FF:FF' + assert received.rorg == 'BS4' + assert received.packet_type == 'RADIO_ERP1' assert received.dbm == -45 + assert (received.status, received.repeater_count) == (0x00, 0) + assert received.eep is None + + +def test_log_fields_match_to_dict(): + registry = DeviceRegistry([Device('01:81:B7:44', EEPId(0xA5, 0x02, 0x05), name='sensor')]) + packet = Packet.parse_msg(bytearray(RADIO_FRAME))[2] + registry.decode(packet) + + fields = packet_log_fields(packet, 'packet_received') + + assert fields.pop('event') == 'packet_received' + assert fields == {key: value for key, value in packet.to_dict().items() if key in fields} + assert fields['eep'] == 'A5-02-05' + + +def test_sent_packets_carry_structured_fields(caplog): + caplog.set_level(logging.DEBUG, logger='enocean') + com = Communicator() + com.send(RadioPacket.create(rorg=RORG.RPS, rorg_func=0x02, rorg_type=0x02, EB='pressed')) + + com._get_from_send_queue() + + [sent] = [r for r in records(caplog, logging.DEBUG) if r.getMessage().startswith('Sending')] + assert sent.event == 'packet_sent' + assert sent.rorg == 'RPS' + assert sent.eep == 'F6-02-02' + assert sent.dbm is None + + +def test_unknown_profile_is_named(caplog): + caplog.set_level(logging.DEBUG, logger='enocean') + packet = Packet.parse_msg(bytearray(RADIO_FRAME))[2] + + assert not packet.select_eep(0x02, 0x7F) + + [warning] = records(caplog, logging.WARNING) + assert warning.event == 'unknown_profile' + assert warning.eep == 'A5-02-7F' + assert warning.command is None + + +def test_unknown_field_is_named(caplog): + caplog.set_level(logging.DEBUG, logger='enocean') + RadioPacket.create(rorg=RORG.BS4, rorg_func=0x02, rorg_type=0x05, TMP=20, XYZ=1) + + [warning] = records(caplog, logging.WARNING) + assert warning.event == 'unknown_field' + assert warning.shortcut == 'XYZ' def test_building_default_packets_does_not_warn(caplog): diff --git a/pyproject.toml b/pyproject.toml index 1c0c698..daa28f1 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "enocean" -version = "2.0.2" +version = "2.1.0" description = "EnOcean serial protocol (ESP3) and equipment profiles (EEP) implementation" readme = "README.md" classifiers = [ diff --git a/uv.lock b/uv.lock index a2e72fa..a43dd63 100644 --- a/uv.lock +++ b/uv.lock @@ -418,7 +418,7 @@ toml = [ [[package]] name = "enocean" -version = "2.0.2" +version = "2.1.0" source = { editable = "." } dependencies = [ { name = "pyserial" },