Rc stable7 7.1.021

Classes/LoggingManagement.py

@@ -136,6 +136,7 @@ def open_logging_mode(self):
         import sys
 
         if not self.pluginconf.pluginConf["enablePluginLogging"]:
+            domoticz_status_api("Z4D Plugin logs are redirected to Domoticz log")
             return
 
         _pluginlogs = Path(self.pluginconf.pluginConf["pluginLogs"] )
@@ -147,7 +148,7 @@ def open_logging_mode(self):
             _backupCount = int(self.pluginconf.pluginConf["loggingBackupCount"])
         if "loggingMaxMegaBytes" in self.pluginconf.pluginConf:
             _maxBytes = int(self.pluginconf.pluginConf["loggingMaxMegaBytes"]) * 1024 * 1024
-        domoticz_status_api("Please watch plugin log into %s" % _logfilename)
+        domoticz_status_api("Z4D Please watch plugin logs into %s" % _logfilename)
         if _maxBytes == 0:
             # Enable TimedRotating
             if sys.version_info >= (3, 9):
@@ -464,7 +465,7 @@ def loggingWriteErrorHistory(self):
 
 
 def start_logging_thread(self):
-    domoticz_log_api("start_logging_thread")
+    #domoticz_log_api("start_logging_thread")
     if self.logging_thread:
         domoticz_error_api("start_logging_thread - Looks like logging_thread already started !!!")
         return
@@ -478,7 +479,7 @@ def start_logging_thread(self):
 
 def logging_thread(self):
 
-    domoticz_log_api("logging_thread - listening")
+    #domoticz_log_api("logging_thread - listening")
     while self.running:
         # We loop until self.running is set to False,
         # which indicate plugin shutdown

Classes/OTA.py

@@ -74,6 +74,7 @@
     "Salus": {"Folder": "SALUS", "ManufCode": 0x1078, "ManufName": "Computime", "Enabled": True},
     "Schneider": {"Folder": "SCHNEIDER-WISER", "ManufCode": 0x105E, "ManufName": "Schneider Electric", "Enabled": True},
     "SonOff": {"Folder": "SONOFF", "ManufCode": 0x1286, "ManufName": "Sonoff", "Enabled": True},
+    "Xiaomi": {"Folder": "XIAOMI", "ManufCode": 0x115f, "ManufName": "Xiaomi", "Enabled": True},
 }
 
 

Classes/PluginConf.py

@@ -402,6 +402,7 @@
         "Order": 99,
         "param": {
             # Just for compatibility keep it but hidden ( move to Custom device "Param" section)
+            "CheckRequirements": {"type": "bool","default": 1,"current": None,"restart": 0,"hidden": True,"Advanced": True},
             "nPDUaPDUThreshold": {"type": "bool","default": 0,"current": None,"restart": 0,"hidden": True,"Advanced": True,"ZigpyRadio": ""},
             "rebindLivolo": {"type": "bool","default": 0,"current": None,"restart": 0,"hidden": True,"Advanced": False,},
             "allowAutoPairing": {"type": "bool","default": 0,"current": None,"restart": 0,"hidden": True,"Advanced": True,},

Classes/WebServer/com.py

@@ -22,7 +22,7 @@
 
 def startWebServer(self):
 
-    self.logging("Status", "WebUI thread started")
+    self.logging("Debug", "WebUI thread started")
     if self.server_thread:
         self.logging("Error", "start_logging_thread - Looks like logging_thread already started !!!")
         return
@@ -367,9 +367,9 @@ def run_server(self, host='0.0.0.0', port=9440):   # nosec
         self.server.settimeout(10)
 
         if context:
-            self.logging("Status", f"WebUI Server started on SSL https://{host}:{port}")
+            self.logging("Log", f"WebUI Server started on SSL https://{host}:{port}")
         else:
-            self.logging("Status", f"WebUI Server started on {host}:{port}")
+            self.logging("Log", f"WebUI Server started on {host}:{port}")
 
         server_loop(self, )
 

Classes/ZigpyTransport/AppBellows.py

@@ -10,7 +10,9 @@
 #
 # SPDX-License-Identifier:    GPL-3.0 license
 
+import asyncio
 import logging
+import time
 
 import bellows.config as bellows_conf
 import bellows.types as t
@@ -63,9 +65,13 @@ async def startup(self, statistics, HardwareID, pluginconf, use_of_zigpy_persist
         self.captureRxFrame = captureRxFrame
         self.use_of_zigpy_persistent_db = use_of_zigpy_persistent_db
 
+        self.start_time = time.time()
+
         self.shutting_down = False
         self.restarting = False
 
+        await asyncio.sleep( 3 )
+
         try:
             await self.connect()
             await self.initialize(auto_form=True, force_form=force_form)

Classes/ZigpyTransport/AppDeconz.py

@@ -12,6 +12,7 @@
 
 import asyncio
 import logging
+import time
 
 import zigpy.config as zigpy_conf
 import zigpy.device
@@ -59,7 +60,9 @@ async def startup(self, statistics, HardwareID, pluginconf, use_of_zigpy_persist
         self.HardwareID = HardwareID
         self.captureRxFrame = captureRxFrame
         self.use_of_zigpy_persistent_db = use_of_zigpy_persistent_db
-
+
+        self.start_time = time.time()
+
         self.shutting_down = False
         self.restarting = False
 

Classes/ZigpyTransport/AppGeneric.py

@@ -41,6 +41,7 @@
 LOGGER = logging.getLogger(__name__)
 
 ENERGY_SCAN_WARN_THRESHOLD = 0.75 * 255
+GRACE_PERIOD_AFTER_START = 60  # 60 seconds of period after plugin start to allow NCP to recover
 
 
 async def _load_db(self) -> None:
@@ -143,9 +144,12 @@ async def shutdown(self, *, db: bool = True) -> None:
     LOGGER.info("Zigpy shutdown")
     self.shutting_down = True
 
+    LOGGER.info("Backup")
     await _create_backup(self)
 
-    await ControllerApplication.shutdown(self, db=db)
+    LOGGER.info("zigpy application shutdown")
+    # await ControllerApplication.shutdown(self, db=db)
+    await super(type(self),self).shutdown( db=db)
 
 
 async def _create_backup(self) -> None:
@@ -159,16 +163,35 @@ async def _create_backup(self) -> None:
 
 def connection_lost(self, exc: Exception) -> None:
     """Handle connection lost event."""
-    LOGGER.warning( "+ Connection to the radio was lost (trying to recover): %s %r" %(type(exc), exc) )
 
-    super(type(self),self).connection_lost(exc)
+    from bellows.ash import NcpFailure  # pylint: disable=import-outside-toplevel
+    from bellows.types.named import NcpResetCode  # pylint: disable=import-outside-toplevel
 
-    if not self.shutting_down and not self.restarting and isinstance( exc, (serial.serialutil.SerialException, TimeoutError)):
-        LOGGER.error( "++++++++++++++++++++++ Connection to coordinator failed on Serial, let's restart the plugin")
-        LOGGER.warning( f"--> : self.shutting_down: {self.shutting_down}, {self.restarting}")
+    LOGGER.warning("+ Connection to the radio was lost: %s %r", type(exc), exc)
 
-        self.restarting = True
-        self.callBackRestartPlugin()
+    if self.shutting_down or self.restarting:
+        LOGGER.warning("+ shutdown or restart in progress")
+        return
+
+    if isinstance(exc, NcpFailure) and exc.code == NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT:
+        # it seems that the NCP is stuck, but during a plugin restart, it usally recovery, so let's give a grace period
+        if time.time() < (self.start_time + GRACE_PERIOD_AFTER_START):
+            LOGGER.warning("+ Connection to the radio was lost, give time for recover ...")
+            return
+
+        connection_lost_error( self, "NCP reset due to exceeded maximum ACK timeout count, plugin restart required" )
+
+    elif isinstance(exc, (serial.serialutil.SerialException, asyncio.CancelledError)):
+        connection_lost_error( self, "Connection to coordinator lost, SerialError or CancelledError, plugin restart required" )
+
+    elif isinstance(exc, (TimeoutError, asyncio.TimeoutError)):
+        connection_lost_error( self, "Connection to coordinator lost, TimeOut, plugin restart required" )
+
+
+def connection_lost_error(self, message: str) -> None:
+    self.restarting = True
+    LOGGER.error(message)
+    self.callBackRestartPlugin()
 
 
 def _retreive_previous_backup(self):
@@ -361,8 +384,9 @@ def packet_received(
     self.log.logging("TransportZigpy", "Debug", "packet_received Sender: %s frame for plugin: %s" % (sender, plugin_frame))
     self.callBackFunction(plugin_frame)
 
-    if cluster == 0x0019:
-        # Do not forward message to zigpy, it will be managed by Z4D plugin
+    if profile == 0x0104 and sender != "0000":
+        # ZCL Message sent by a device to the coordinator. 
+        # Leave the answer to the plugin and not zigpy layer
         return
 
     super(type(self),self).packet_received(packet)

Classes/ZigpyTransport/AppZnp.py

@@ -10,7 +10,9 @@
 #
 # SPDX-License-Identifier:    GPL-3.0 license
 
+import asyncio
 import logging
+import time
 
 import zigpy.config as zigpy_conf
 import zigpy.device
@@ -64,9 +66,13 @@ async def startup(self, statistics, HardwareID, pluginconf, use_of_zigpy_persist
         self.captureRxFrame = captureRxFrame
         self.use_of_zigpy_persistent_db = use_of_zigpy_persistent_db
 
+        self.start_time = time.time()
+
         self.shutting_down = False
         self.restarting = False
 
+        await asyncio.sleep( 3 )
+
         # Pipiche : 24-Oct-2022 Disabling CONF_MAX_CONCURRENT_REQUESTS so the default will be used ( 16 )
         # self.znp_config[znp_conf.CONF_MAX_CONCURRENT_REQUESTS] = 2
 

Classes/ZigpyTransport/zigpyThread.py

@@ -110,7 +110,7 @@ def zigpy_thread_function(self):
     if self.pluginconf.pluginConf.get("EventLoopInstrumentation", False):
         zigpy_loop.set_debug(True)
 
-    self.log.logging("TransportZigpy", "Log", f"zigpyThread EventLoop: {zigpy_loop}")
+    self.log.logging("TransportZigpy", "Debug", f"zigpyThread EventLoop: {zigpy_loop}")
 
     try:
         # Run the Zigpy task asynchronously
@@ -178,12 +178,16 @@ async def start_zigpy_task(self, channel, extended_pan_id):
 
     # We exit the worker_loop, shutdown time
     try:
+        self.log.logging("TransportZigpy", "Log", "Shutding down zigpy thread")
         await self.app.shutdown()
 
     except Exception as e:
         self.log.logging("TransportZigpy", "Error", f"start_zigpy_task shutdown(self) error: {e}")
         self.log.logging("TransportZigpy", "Error", f" {str(traceback.format_exc())}")
 
+        self.log.logging("TransportZigpy", "Log", "Disconnecting communication")
+        await self.app.disconnect()
+
     #await asyncio.gather(task, return_exceptions=False)
     await asyncio.sleep(1)
 

Conf/ZclDefinitions/0001.json

@@ -1,7 +1,7 @@
 {
     "ClusterId": "0001",
     "Description": "Power",
-    "Version": "1",
+    "Version": "1.2",
     "Enabled": true,
     "Attributes": {
         "0000": { 
@@ -89,7 +89,7 @@
             "Acc": "RP" ,
             "Default": "0",
             "Mandatory": false,
-            "ActionList": [ "check_store_value", "upd_domo_device", "update_battery", "update_battery_percentage"]
+            "ActionList": [ "check_store_value", "update_battery", "update_battery_percentage"]
         },
 
         "0030": { "Enabled": true, "Name": "BatteryManufacturer", "DataType": "41", "ActionList": [ "check_store_value"] },

Modules/inRawAps.py

@@ -69,7 +69,7 @@ def inRawAps( self, Devices, srcnwkid, srcep, cluster, dstnwkid, dstep, Sqn, Glo
     self.log.logging( "inRawAPS", "Debug", "inRawAps Nwkid: %s Ep: %s Cluster: %s ManufCode: %s Cmd: %s Data: %s" % (
         srcnwkid, srcep, cluster, ManufacturerCode, Command, Data), srcnwkid, )
 
-    model_name = self.ListOfDevices[srcnwkid]["Model"] if "Model" in self.ListOfDevices[srcnwkid] else ""
+    model_name = self.ListOfDevices[srcnwkid].get("Model", "")
 
     if cluster == "0020":  # Poll Control ( Not implemented in firmware )
         # self.log.logging("inRawAPS","Log","Cluster 0020 -- POLL CLUSTER")