From e52a7b0f293895d93fc272657f75492c3469f8af Mon Sep 17 00:00:00 2001 From: Pipiche <8291674+pipiche38@users.noreply.github.com> Date: Sat, 8 Jun 2024 17:24:20 +0200 Subject: [PATCH] cleaning up logs messages / refactor submit request (#1745) * cleaning up logs messages * check if we do not miss an unexpected Exception * zigpy mrequest(), broadcast() and request() becoming obsolete. Refactor based on send_packet() --- Classes/ZigpyTransport/zigpyThread.py | 116 +++++++++++++++++++++++--- Modules/readAttributes.py | 14 +--- 2 files changed, 107 insertions(+), 23 deletions(-) diff --git a/Classes/ZigpyTransport/zigpyThread.py b/Classes/ZigpyTransport/zigpyThread.py index acfaa3df4..57f9762a9 100644 --- a/Classes/ZigpyTransport/zigpyThread.py +++ b/Classes/ZigpyTransport/zigpyThread.py @@ -507,7 +507,7 @@ async def process_raw_command(self, data, AckIsDisable=False, Sqn=None): self.log.logging("TransportZigpy", "Debug", f"process_raw_command: extended_timeout {extended_timeout}") delay = data.get("Delay", None) - self.log.logging("TransportZigpy", "Debug", f"process_raw_command: process_raw_command ready to request Function: {Function} NwkId: {NwkId}/{dEp} Cluster: {Cluster} Seq: {sequence} Payload: {payload.hex()} AddrMode: {addressmode} EnableAck: {not AckIsDisable}, Sqn: {Sqn}, Delay: {delay}, Extended_TO: {extended_timeout}") + self.log.logging("TransportZigpy", "Debug", f"process_raw_command: process_raw_command ready to request Function: {Function} NwkId: {NwkId}/{dEp} Cluster: {Cluster} Seq: {sequence} Payload: {payload.hex()} AddrMode: {addressmode} AckIsDisable: {AckIsDisable} EnableAck: {not AckIsDisable}, Sqn: {Sqn}, Delay: {delay}, Extended_TO: {extended_timeout}") destination, transport_needs = _get_destination(self, NwkId, addressmode, Profile, Cluster, sEp, dEp, sequence, payload) @@ -683,7 +683,7 @@ def check_transport_readiness(self): def measure_execution_time(func): - async def wrapper(self, Function, destination, Profile, Cluster, sEp, dEp, sequence, payload, ack_is_disable=False, use_ieee=False, delay=None, extended_timeout=False): + async def wrapper(self, Function, destination, Profile, Cluster, sEp, dEp, sequence, payload, ack_is_disable, use_ieee, delay, extended_timeout): t_start = None if self.pluginconf.pluginConf.get("ZigpyReactTime", False): t_start = int(1000 * time.time()) @@ -696,7 +696,7 @@ async def wrapper(self, Function, destination, Profile, Cluster, sEp, dEp, seque t_end = int(1000 * time.time()) t_elapse = t_end - t_start self.statistics.add_timing_zigpy(t_elapse) - self.log.logging("TransportZigpy", "Log", f"| (transport_request) | {t_elapse} | {Function} | {destination.nwk} | {destination.ieee} | {destination.model} | {destination.manufacturer_id} | {destination.is_initialized} | {destination.rssi} | {destination.lqi} |") + self.log.logging("TransportZigpy", "Log", f"| (transport_request) | {t_elapse} | {Function} | {sequence} | {ack_is_disable} | {destination.nwk} | {destination.ieee} | {destination.model} | {destination.manufacturer_id} | {destination.is_initialized} | {destination.rssi} | {destination.lqi} |") return wrapper @@ -742,15 +742,16 @@ async def transport_request(self, Function, destination, Profile, Cluster, sEp, async def _send_and_retry(self, Function, destination, Profile, Cluster, _nwkid, sEp, dEp, sequence, payload, use_ieee, _ieee, ack_is_disable, extended_timeout): - max_retry = MAX_ATTEMPS_REQUEST if self.pluginconf.pluginConf["PluginRetrys"] else 1 + max_retry = MAX_ATTEMPS_REQUEST if self.pluginconf.pluginConf["PluginRetrys"] else 1 + for attempt in range(1, (max_retry + 1)): try: - self.log.logging("TransportZigpy", "Debug", f"_send_and_retry: {_ieee} {Profile} {Cluster} - Expect_Reply: {ack_is_disable} extended_timeout: {extended_timeout} Attempts: {attempt}/{max_retry}") - result, msg = await self.app.request(destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply=not ack_is_disable, use_ieee=use_ieee, extended_timeout=extended_timeout) + self.log.logging("TransportZigpy", "Debug", f"_send_and_retry: {_ieee} {Profile} {Cluster} - AckIsDisable: {ack_is_disable} extended_timeout: {extended_timeout} Attempts: {attempt}/{max_retry}") + result, _ = await zigpy_request(self, destination, Profile, Cluster, sEp, dEp, sequence, payload, ack_is_disable=ack_is_disable, use_ieee=use_ieee, extended_timeout=extended_timeout) except (asyncio.exceptions.TimeoutError, asyncio.exceptions.CancelledError, AttributeError, DeliveryError) as e: - error_log_message = f"{Function} {_ieee}/0x{_nwkid} 0x{Profile} 0x{Cluster}:16 Ack: {ack_is_disable} RETRY: {attempt}/{max_retry} ({e})" + error_log_message = f"Warning while submitting - {Function} {_ieee}/0x{_nwkid} 0x{Profile} 0x{Cluster}:16 AckIsDisable: {ack_is_disable} Retry: {attempt}/{max_retry} with exception ({e})" self.log.logging("TransportZigpy", "Log", error_log_message) if await _retry_or_not(self, attempt, max_retry, Function, sequence, ack_is_disable, _ieee, _nwkid, destination, e): @@ -762,12 +763,108 @@ async def _send_and_retry(self, Function, destination, Profile, Cluster, _nwkid, self.statistics._ackKO += 1 break + except Exception as error: + # Any other exception + error_log_message = f"_send_and_retry - Unexpected Exception - {Function} {_ieee}/0x{_nwkid} 0x{Profile} 0x{Cluster}:16 AckIsDisable: {ack_is_disable} RETRY: {attempt}/{max_retry} ({error})" + self.log.logging("TransportZigpy", "Error", error_log_message) + result = 0xB6 + else: # Success handle_transport_result(self, Function, sequence, result, ack_is_disable, _ieee, _nwkid, destination.lqi) - self.log.logging("TransportZigpy", "Debug", f"transport_request: result: {result}") + self.log.logging("TransportZigpy", "Debug", f"_send_and_retry: result: {result}") break + +async def zigpy_request( self, device: zigpy.device.Device, profile: t.uint16_t, cluster: t.uint16_t, src_ep: t.uint8_t, dst_ep: t.uint8_t, sequence: t.uint8_t, data: bytes, *, ack_is_disable: bool = True, use_ieee: bool = False, extended_timeout: bool = False, ) -> tuple[zigpy.zcl.foundation.Status, str]: + """Submit and send data out as an unicast transmission.""" + + self.log.logging( + "TransportZigpy", + "Debug", + f"zigpy_request: " + f"zigpy_request called with: device={device}, profile={profile}, cluster={cluster}, " + f"src_ep={src_ep}, dst_ep={dst_ep}, sequence={sequence}, data={data}, " + f"ack_is_disable={ack_is_disable}, use_ieee={use_ieee}, extended_timeout={extended_timeout}" + ) + if use_ieee: + src = t.AddrModeAddress( addr_mode=t.AddrMode.IEEE, address=self.app.state.node_info.ieee ) + dst = t.AddrModeAddress(addr_mode=t.AddrMode.IEEE, address=device.ieee) + else: + src = t.AddrModeAddress( addr_mode=t.AddrMode.NWK, address=self.app.state.node_info.nwk ) + dst = t.AddrModeAddress(addr_mode=t.AddrMode.NWK, address=device.nwk) + + if self.app.config[zigpy.config.CONF_SOURCE_ROUTING]: + source_route = self.app.build_source_route_to(dest=device) + else: + source_route = None + + tx_options = t.TransmitOptions.NONE + + if not ack_is_disable: + tx_options |= t.TransmitOptions.ACK + + await self.app.send_packet( + t.ZigbeePacket( + src=src, + src_ep=src_ep, + dst=dst, + dst_ep=dst_ep, + tsn=sequence, + profile_id=profile, + cluster_id=cluster, + data=t.SerializableBytes(data), + extended_timeout=extended_timeout, + source_route=source_route, + tx_options=tx_options, + ) + ) + + return (zigpy.zcl.foundation.Status.SUCCESS, "") + + +async def zigpy_mrequest( self, group_id: t.uint16_t, profile: t.uint8_t, cluster: t.uint16_t, src_ep: t.uint8_t, sequence: t.uint8_t, data: bytes, *, hops: int = 0, non_member_radius: int = 3,): + """Submit and send data out as a multicast transmission.""" + + await self.app.send_packet( + t.ZigbeePacket( + src=t.AddrModeAddress( addr_mode=t.AddrMode.NWK, address=self.state.node_info.nwk ), + src_ep=src_ep, + dst=t.AddrModeAddress(addr_mode=t.AddrMode.Group, address=group_id), + tsn=sequence, + profile_id=profile, + cluster_id=cluster, + data=t.SerializableBytes(data), + tx_options=t.TransmitOptions.NONE, + radius=hops, + non_member_radius=non_member_radius, + ) + ) + + return (zigpy.zcl.foundation.Status.SUCCESS, "") + + +async def zigpy_broadcast( self, profile: t.uint16_t, cluster: t.uint16_t, src_ep: t.uint8_t, dst_ep: t.uint8_t, grpid: t.uint16_t, radius: int, sequence: t.uint8_t, data: bytes, broadcast_address: t.BroadcastAddress = t.BroadcastAddress.RX_ON_WHEN_IDLE, ) -> tuple[zigpy.zcl.foundation.Status, str]: + """Submit and send data out as an unicast transmission.""" + + await self.app.send_packet( + t.ZigbeePacket( + src=t.AddrModeAddress( addr_mode=t.AddrMode.NWK, address=self.state.node_info.nwk ), + src_ep=src_ep, + dst=t.AddrModeAddress( addr_mode=t.AddrMode.Broadcast, address=broadcast_address ), + dst_ep=dst_ep, + tsn=sequence, + profile_id=profile, + cluster_id=cluster, + data=t.SerializableBytes(data), + tx_options=t.TransmitOptions.NONE, + radius=radius, + ) + ) + + return (zigpy.zcl.foundation.Status.SUCCESS, "") + + async def _retry_or_not(self, attempt, max_retry, Function, sequence,ack_is_disable, _ieee, _nwkid, destination , e): if attempt < max_retry: # Slow down the throughput when too many commands. Try not to overload the coordinators @@ -783,8 +880,7 @@ async def _retry_or_not(self, attempt, max_retry, Function, sequence,ack_is_disa def handle_transport_result(self, Function, sequence, result, ack_is_disable, _ieee, _nwkid, lqi): - self.log.logging("TransportZigpy", "Debug", f"handle_transport_result - {Function} - {_nwkid} - Ack: {ack_is_disable} Result: {result}") - #if not ack_is_disable: + self.log.logging("TransportZigpy", "Debug", f"handle_transport_result - {Function} - {_nwkid} - AckIsDisable: {ack_is_disable} Result: {result}") push_APS_ACK_NACKto_plugin(self, _nwkid, result, lqi) if result == 0x00 and _ieee in self._currently_not_reachable: diff --git a/Modules/readAttributes.py b/Modules/readAttributes.py index 7893a0086..9920351bb 100644 --- a/Modules/readAttributes.py +++ b/Modules/readAttributes.py @@ -313,19 +313,7 @@ def ping_device_with_read_attribute(self, key): for EPout in ListOfEp: check_datastruct(self, "ReadAttributes", key, EPout, PING_CLUSTER) - i_sqn = read_attribute( - self, - key, - ZIGATE_EP, - EPout, - PING_CLUSTER, - "00", - "00", - "0000", - "%02x" % (0x01), - PING_CLUSTER_ATTRIBUTE, - ackIsDisabled=False, - ) + i_sqn = read_attribute( self, key, ZIGATE_EP, EPout, PING_CLUSTER, "00", "00", "0000", "%02x" % (0x01), PING_CLUSTER_ATTRIBUTE, ackIsDisabled=False, ) set_isqn_datastruct(self, "ReadAttributes", key, EPout, PING_CLUSTER, PING_CLUSTER_ATTRIBUTE, i_sqn) # Let's ping only 1 EndPoint