From d10aa502a093157a59353ba0f6c6285562244c5b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jan=20Kundr=C3=A1t?= Date: Fri, 26 Jul 2024 17:06:06 +0200 Subject: [PATCH 1/2] tridonic: log failures from the bus_watcher These were all logged as debug messages, which means that they are not shown by default. This makes any debugging of failures much harder, see, e.g., #124. --- dali/driver/hid.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/dali/driver/hid.py b/dali/driver/hid.py index 4523012..ef6ac6b 100644 --- a/dali/driver/hid.py +++ b/dali/driver/hid.py @@ -518,7 +518,7 @@ async def _bus_watch(self): self._log.debug("bus_watch message %s", _hex(message[0:9])) origin, rtype, raw_frame, interval, seq = self._resptmpl.unpack(message) if origin not in (self._MODE_OBSERVE, self._MODE_RESPONSE): - self._log.debug("bus_watch: unexpected packet mode, ignoring") + self._log.warning("bus_watch: unexpected packet mode, ignoring") continue if rtype == self._RESPONSE_FRAME_DALI16: frame = dali.frame.ForwardFrame(16, raw_frame) @@ -545,7 +545,7 @@ async def _bus_watch(self): # We are waiting for a repeat of the command if timeout: # We didn't get it: report a failed command - self._log.debug("Failed sendtwice command: %s", current_command) + self._log.warning("Failed sendtwice command: %s", current_command) self.bus_traffic._invoke(current_command, None, True) current_command = None continue @@ -557,18 +557,18 @@ async def _bus_watch(self): current_command = None continue else: - self._log.debug("Failed config command (second frame didn't match): %s", current_command) + self._log.warning("Failed config command (second frame didn't match): %s", current_command) self.bus_traffic._invoke(current_command, None, True) current_command = None # Fall through to continue processing frame elif isinstance(frame, dali.frame.BackwardFrame): # Error: config commands don't get backward frames. - self._log.debug("Failed config command %s with backward frame", + self._log.error("Failed config command %s with backward frame", current_command) self.bus_traffic._invoke(current_command, None, True) current_command = None else: - self._log.debug("Unexpected response waiting for retransmit of config command") + self._log.error("Unexpected response waiting for retransmit of config command, frame = %s", frame) elif current_command.response: # We are waiting for a response if timeout or frame == "no": From 1d455902a4b4ebd7c19e5f6a994868d0ae3c2061 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jan=20Kundr=C3=A1t?= Date: Fri, 26 Jul 2024 17:07:47 +0200 Subject: [PATCH 2/2] tridonic: prevent a possible AssertionFailure I was playing with some commands, and one of my devices apparently just won't send any reply to a DT5 ResetConverterSettings. That's a sendtwice=True command, and when that happens, I was getting an assertion failure later on on line 600, which looks pretty much like bug #124: 15:00:59.333780 D: tridonic: Sending with seq e7 15:00:59.339550 D: tridonic: waiting for outstanding_transmissions=1 {response=} 15:00:59.357560 D: tridonic: _handle_read 12730000C105FFFFE7 15:00:59.363037 D: tridonic: bus_watch message 12730000C105FFFFE7 15:00:59.368941 D: tridonic: Command EnableDeviceType(5), immediate 15:00:59.384012 D: tridonic: remembering device type 5 15:00:59.387287 D: tridonic: Bus watch waiting for data, no timeout 15:00:59.400013 D: tridonic: message mode=12 rtype=73 frame=b'\x00\x00\xc1\x05' interval=ffff seq=e7 15:00:59.403352 D: tridonic: waiting for outstanding_transmissions=0 {response=} 15:00:59.407774 I: dali: EnableDeviceType(5) 15:00:59.431360 D: tridonic: _handle_read 127100000000008AE7 15:00:59.454305 D: tridonic: bus_watch message 127100000000008AE7 15:00:59.457782 D: tridonic: Bus watch waiting for data, no timeout 15:00:59.461983 D: tridonic: message mode=12 rtype=71 frame=b'\x00\x00\x00\x00' interval=008a seq=e7 15:00:59.693383 D: tridonic: Sending with seq e8 15:00:59.698993 D: tridonic: waiting for outstanding_transmissions=1 {response=} 15:00:59.716567 D: tridonic: _handle_read 1273000001E6103BE8 15:00:59.721514 D: tridonic: bus_watch message 1273000001E6103BE8 15:00:59.727816 D: tridonic: Bus watch waiting with timeout 15:00:59.732960 D: tridonic: message mode=12 rtype=73 frame=b'\x00\x00\x01\xe6' interval=103b seq=e8 15:00:59.736298 D: tridonic: waiting for outstanding_transmissions=0 {response=} 15:00:59.741356 D: tridonic: _handle_read 127100000000008AE8 15:00:59.746287 D: tridonic: message mode=12 rtype=71 frame=b'\x00\x00\x00\x00' interval=008a seq=e8 15:00:59.785298 D: tridonic: bus_watch message 127100000000008AE8 15:00:59.788843 D: tridonic: Unexpected response waiting for retransmit of config command 15:00:59.794324 E: tridonic: current_command is not None: ResetConverterSettings(
) I'm not saying that this is surely a fix for #124, but that one was happening in an environment where DT8 Tc commands were sent regularly. --- dali/driver/hid.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/dali/driver/hid.py b/dali/driver/hid.py index ef6ac6b..9a4c79e 100644 --- a/dali/driver/hid.py +++ b/dali/driver/hid.py @@ -567,6 +567,11 @@ async def _bus_watch(self): current_command) self.bus_traffic._invoke(current_command, None, True) current_command = None + elif frame == "no": + self._log.warning("No frame in response to a sendtwice command: %s", current_command) + self.bus_traffic._invoke(current_command, None, True) + current_command = None + continue else: self._log.error("Unexpected response waiting for retransmit of config command, frame = %s", frame) elif current_command.response: