[Python] Adjust logging levels in Python controller (#34346)

Use global loggers per-module which is more Pythonic and avoids
unnecessary logger instances. Also use the module name as the logger
name consistently.

Avoid using the warning level for messages which are really only
informational. Also lower the log level of storage messages to debug,
as they are really not that important. Drop some unnecessary logs
like on every storage commit.

Author: agners

src/controller/python/chip/CertificateAuthority.py

@@ -28,6 +28,8 @@
 from chip.native import PyChipError
 from chip.storage import PersistentStorage
 
+LOGGER = logging.getLogger(__name__)
+
 
 class CertificateAuthority:
     '''  This represents an operational Root Certificate Authority (CA) with a root key key pair with associated
@@ -64,7 +66,7 @@ def __init__(self, chipStack: ChipStack.ChipStack, caIndex: int, persistentStora
                 persistentStorage:  An optional reference to a PersistentStorage object. If one is provided, it will pick that over
                                     the default PersistentStorage object retrieved from the chipStack.
         '''
-        self.logger().warning(f"New CertificateAuthority at index {caIndex}")
+        LOGGER.info(f"New CertificateAuthority at index {caIndex}")
 
         self._chipStack = chipStack
         self._caIndex = caIndex
@@ -105,7 +107,7 @@ def LoadFabricAdminsFromStorage(self):
         if (not (self._isActive)):
             raise RuntimeError("Object isn't active")
 
-        self.logger().warning("Loading fabric admins from storage...")
+        LOGGER.info("Loading fabric admins from storage...")
 
         caList = self._persistentStorage.GetReplKey(key='caList')
         if (str(self._caIndex) not in caList):
@@ -244,7 +246,7 @@ def LoadAuthoritiesFromStorage(self):
         if (not (self._isActive)):
             raise RuntimeError("Object is not active")
 
-        self.logger().warning("Loading certificate authorities from storage...")
+        LOGGER.info("Loading certificate authorities from storage...")
 
         #
         # Persist details to storage (read modify write).

src/controller/python/chip/ChipDeviceCtrl.py

@@ -61,6 +61,8 @@
 # Defined in $CHIP_ROOT/src/lib/core/CHIPError.h
 CHIP_ERROR_TIMEOUT: int = 50
 
+LOGGER = logging.getLogger(__name__)
+
 _DevicePairingDelegate_OnPairingCompleteFunct = CFUNCTYPE(None, PyChipError)
 _DeviceUnpairingCompleteFunct = CFUNCTYPE(None, c_uint64, PyChipError)
 _DevicePairingDelegate_OnCommissioningCompleteFunct = CFUNCTYPE(
@@ -401,17 +403,17 @@ def __init__(self, name: str = ''):
     def _set_dev_ctrl(self, devCtrl, pairingDelegate):
         def HandleCommissioningComplete(nodeId: int, err: PyChipError):
             if err.is_success:
-                logging.info("Commissioning complete")
+                LOGGER.info("Commissioning complete")
             else:
-                logging.warning("Failed to commission: {}".format(err))
+                LOGGER.warning("Failed to commission: {}".format(err))
 
             self._dmLib.pychip_DeviceController_SetIcdRegistrationParameters(False, None)
 
             if self._dmLib.pychip_TestCommissionerUsed():
                 err = self._dmLib.pychip_GetCompletionError()
 
             if self._commissioning_context.future is None:
-                logging.exception("HandleCommissioningComplete called unexpectedly")
+                LOGGER.exception("HandleCommissioningComplete called unexpectedly")
                 return
 
             if err.is_success:
@@ -425,14 +427,14 @@ def HandleFabricCheck(nodeId):
         def HandleOpenWindowComplete(nodeid: int, setupPinCode: int, setupManualCode: str,
                                      setupQRCode: str, err: PyChipError) -> None:
             if err.is_success:
-                logging.info("Open Commissioning Window complete setting nodeid {} pincode to {}".format(nodeid, setupPinCode))
+                LOGGER.info("Open Commissioning Window complete setting nodeid {} pincode to {}".format(nodeid, setupPinCode))
                 commissioningParameters = CommissioningParameters(
                     setupPinCode=setupPinCode, setupManualCode=setupManualCode.decode(), setupQRCode=setupQRCode.decode())
             else:
-                logging.warning("Failed to open commissioning window: {}".format(err))
+                LOGGER.warning("Failed to open commissioning window: {}".format(err))
 
             if self._open_window_context.future is None:
-                logging.exception("HandleOpenWindowComplete called unexpectedly")
+                LOGGER.exception("HandleOpenWindowComplete called unexpectedly")
                 return
 
             if err.is_success:
@@ -442,12 +444,12 @@ def HandleOpenWindowComplete(nodeid: int, setupPinCode: int, setupManualCode: st
 
         def HandleUnpairDeviceComplete(nodeid: int, err: PyChipError):
             if err.is_success:
-                logging.info("Succesfully unpaired device with nodeid {}".format(nodeid))
+                LOGGER.info("Succesfully unpaired device with nodeid {}".format(nodeid))
             else:
-                logging.warning("Failed to unpair device: {}".format(err))
+                LOGGER.warning("Failed to unpair device: {}".format(err))
 
             if self._unpair_device_context.future is None:
-                logging.exception("HandleUnpairDeviceComplete called unexpectedly")
+                LOGGER.exception("HandleUnpairDeviceComplete called unexpectedly")
                 return
 
             if err.is_success:
@@ -457,9 +459,9 @@ def HandleUnpairDeviceComplete(nodeid: int, err: PyChipError):
 
         def HandlePASEEstablishmentComplete(err: PyChipError):
             if not err.is_success:
-                logging.warning("Failed to establish secure session to device: {}".format(err))
+                LOGGER.warning("Failed to establish secure session to device: {}".format(err))
             else:
-                logging.info("Established secure session with Device")
+                LOGGER.info("Established secure session with Device")
 
             if self._commissioning_context.future is not None:
                 # During Commissioning, HandlePASEEstablishmentComplete will also be called.
@@ -469,7 +471,7 @@ def HandlePASEEstablishmentComplete(err: PyChipError):
                 return
 
             if self._pase_establishment_context.future is None:
-                logging.exception("HandlePASEEstablishmentComplete called unexpectedly")
+                LOGGER.exception("HandlePASEEstablishmentComplete called unexpectedly")
                 return
 
             if err.is_success:
@@ -926,7 +928,7 @@ def GetConnectedDeviceSync(self, nodeid, allowPASE=True, timeoutMs: int = None):
             res = self._ChipStack.Call(lambda: self._dmLib.pychip_GetDeviceBeingCommissioned(
                 self.devCtrl, nodeid, byref(returnDevice)), timeoutMs)
             if res.is_success:
-                logging.info('Using PASE connection')
+                LOGGER.info('Using PASE connection')
                 return DeviceProxyWrapper(returnDevice, DeviceProxyWrapper.DeviceProxyType.COMMISSIONEE, self._dmLib)
 
         class DeviceAvailableClosure():
@@ -992,7 +994,7 @@ async def GetConnectedDevice(self, nodeid, allowPASE: bool = True, timeoutMs: in
             res = await self._ChipStack.CallAsync(lambda: self._dmLib.pychip_GetDeviceBeingCommissioned(
                 self.devCtrl, nodeid, byref(returnDevice)), timeoutMs)
             if res.is_success:
-                logging.info('Using PASE connection')
+                LOGGER.info('Using PASE connection')
                 return DeviceProxyWrapper(returnDevice, DeviceProxyWrapper.DeviceProxyType.COMMISSIONEE, self._dmLib)
 
         eventLoop = asyncio.get_running_loop()
@@ -1348,7 +1350,6 @@ def _parseEventPathTuple(self, pathTuple: typing.Union[
             # Wildcard
             return ClusterAttribute.EventPath()
         elif not isinstance(pathTuple, tuple):
-            logging.debug(type(pathTuple))
             if isinstance(pathTuple, int):
                 return ClusterAttribute.EventPath(EndpointId=pathTuple)
             elif issubclass(pathTuple, ClusterObjects.Cluster):
@@ -2115,7 +2116,7 @@ async def CommissionIP(self, ipaddr: str, setupPinCode: int, nodeid: int) -> int
 
     def NOCChainCallback(self, nocChain):
         if self._issue_node_chain_context.future is None:
-            logging.exception("NOCChainCallback while not expecting a callback")
+            LOGGER.exception("NOCChainCallback while not expecting a callback")
             return
         self._issue_node_chain_context.future.set_result(nocChain)
         return

src/controller/python/chip/FabricAdmin.py

@@ -25,6 +25,8 @@
 from chip.crypto import p256keypair
 from chip.native import GetLibraryHandle
 
+LOGGER = logging.getLogger(__name__)
+
 
 class FabricAdmin:
     ''' Administers a fabric associated with a unique FabricID under a given CertificateAuthority
@@ -34,10 +36,6 @@ class FabricAdmin:
     def _Handle(cls):
         return GetLibraryHandle()
 
-    @classmethod
-    def logger(cls):
-        return logging.getLogger('FabricAdmin')
-
     def __init__(self, certificateAuthority: CertificateAuthority.CertificateAuthority, vendorId: int, fabricId: int = 1):
         ''' Initializes the object.
 
@@ -60,7 +58,7 @@ def __init__(self, certificateAuthority: CertificateAuthority.CertificateAuthori
         self._fabricId = fabricId
         self._certificateAuthority = certificateAuthority
 
-        self.logger().warning(f"New FabricAdmin: FabricId: 0x{self._fabricId:016X}, VendorId = 0x{self.vendorId:04X}")
+        LOGGER.info(f"New FabricAdmin: FabricId: 0x{self._fabricId:016X}, VendorId = 0x{self.vendorId:04X}")
 
         self._isActive = True
         self._activeControllers = []
@@ -94,7 +92,7 @@ def NewController(self, nodeId: int = None, paaTrustStorePath: str = "",
             if (nodeId in nodeIdList):
                 raise RuntimeError(f"Provided NodeId {nodeId} collides with an existing controller instance!")
 
-        self.logger().warning(
+        LOGGER.info(
             f"Allocating new controller with CaIndex: {self._certificateAuthority.caIndex}, "
             f"FabricId: 0x{self._fabricId:016X}, NodeId: 0x{nodeId:016X}, CatTags: {catTags}")
 

src/controller/python/chip/clusters/Attribute.py

@@ -40,6 +40,8 @@
 
 from .ClusterObjects import Cluster, ClusterAttributeDescriptor, ClusterEvent
 
+LOGGER = logging.getLogger(__name__)
+
 
 @unique
 class EventTimestampType(Enum):
@@ -569,7 +571,7 @@ def subscriptionId(self) -> int:
 
     def Shutdown(self):
         if (self._isDone):
-            print("Subscription was already terminated previously!")
+            LOGGER.warning("Subscription 0x%08x was already terminated previously!", self.subscriptionId)
             return
 
         handle = chip.native.GetLibraryHandle()
@@ -675,7 +677,7 @@ def handleAttributeData(self, path: AttributePath, dataVersion: int, status: int
             self._changedPathSet.add(path)
 
         except Exception as ex:
-            logging.exception(ex)
+            LOGGER.exception(ex)
 
     def handleEventData(self, header: EventHeader, path: EventPath, data: bytes, status: int):
         try:
@@ -693,12 +695,12 @@ def handleEventData(self, header: EventHeader, path: EventPath, data: bytes, sta
                     try:
                         eventValue = eventType.FromTLV(data)
                     except Exception as ex:
-                        logging.error(
+                        LOGGER.error(
                             f"Error convering TLV to Cluster Object for path: Endpoint = {path.EndpointId}/"
                             f"Cluster = {path.ClusterId}/Event = {path.EventId}")
-                        logging.error(
+                        LOGGER.error(
                             f"Failed Cluster Object: {str(eventType)}")
-                        logging.error(ex)
+                        LOGGER.error(ex)
                         eventValue = ValueDecodeFailure(
                             tlvData, ex)
 
@@ -715,7 +717,7 @@ def handleEventData(self, header: EventHeader, path: EventPath, data: bytes, sta
                     eventResult, self._subscription_handler)
 
         except Exception as ex:
-            logging.exception(ex)
+            LOGGER.exception(ex)
 
     def handleError(self, chipError: PyChipError):
         self._resultError = chipError
@@ -726,7 +728,6 @@ def _handleSubscriptionEstablished(self, subscriptionId):
                 self, subscriptionId, self._devCtrl)
             self._future.set_result(self._subscription_handler)
         else:
-            logging.info("Re-subscription succeeded!")
             if self._subscription_handler._onResubscriptionSucceededCb is not None:
                 if (self._subscription_handler._onResubscriptionSucceededCb_isAsync):
                     self._event_loop.create_task(
@@ -761,7 +762,7 @@ def _handleReportEnd(self):
                     attribute_path = TypedAttributePath(Path=change)
                 except (KeyError, ValueError) as err:
                     # path could not be resolved into a TypedAttributePath
-                    logging.getLogger(__name__).exception(err)
+                    LOGGER.exception(err)
                     continue
                 self._subscription_handler.OnAttributeChangeCb(
                     attribute_path, self._subscription_handler)
@@ -816,7 +817,7 @@ def handleResponse(self, path: AttributePath, status: int):
             imStatus = chip.interaction_model.Status(status)
             self._resultData.append(AttributeWriteResult(Path=path, Status=imStatus))
         except ValueError as ex:
-            logging.exception(ex)
+            LOGGER.exception(ex)
 
     def handleError(self, chipError: PyChipError):
         self._resultError = chipError

src/controller/python/chip/storage/__init__.py

@@ -29,6 +29,8 @@
 import chip.exceptions
 import chip.native
 
+LOGGER = logging.getLogger(__name__)
+
 _SyncSetKeyValueCbFunct = CFUNCTYPE(
     None, py_object, c_char_p, POINTER(c_char),  c_uint16)
 _SyncGetKeyValueCbFunct = CFUNCTYPE(
@@ -91,9 +93,6 @@ class PersistentStorage:
 
         Object must be resident before the Matter stack starts up and last past its shutdown.
     '''
-    @classmethod
-    def logger(cls):
-        return logging.getLogger('PersistentStorage')
 
     def __init__(self, path: str = None, jsonData: Dict = None):
         ''' Initializes the object with either a path to a JSON file that contains the configuration OR
@@ -109,9 +108,9 @@ def __init__(self, path: str = None, jsonData: Dict = None):
             raise ValueError("Can't provide both a valid path and jsonData")
 
         if (path is not None):
-            self.logger().warn(f"Initializing persistent storage from file: {path}")
+            LOGGER.info(f"Initializing persistent storage from file: {path}")
         else:
-            self.logger().warn("Initializing persistent storage from dict")
+            LOGGER.info("Initializing persistent storage from dict")
 
         self._handle = chip.native.GetLibraryHandle()
         self._isActive = True
@@ -125,24 +124,24 @@ def __init__(self, path: str = None, jsonData: Dict = None):
                 self._file.seek(0)
 
                 if (size != 0):
-                    self.logger().warn(f"Loading configuration from {path}...")
+                    LOGGER.info(f"Loading configuration from {path}...")
                     self._jsonData = json.load(self._file)
                 else:
                     self._jsonData = {}
 
             except Exception as ex:
-                logging.error(ex)
-                logging.critical(f"Could not load configuration from {path} - resetting configuration...")
+                LOGGER.error(ex)
+                LOGGER.critical(f"Could not load configuration from {path} - resetting configuration...")
                 self._jsonData = {}
         else:
             self._jsonData = jsonData
 
         if ('sdk-config' not in self._jsonData):
-            logging.warn("No valid SDK configuration present - clearing out configuration")
+            LOGGER.warn("No valid SDK configuration present - clearing out configuration")
             self._jsonData['sdk-config'] = {}
 
         if ('repl-config' not in self._jsonData):
-            logging.warn("No valid REPL configuration present - clearing out configuration")
+            LOGGER.warn("No valid REPL configuration present - clearing out configuration")
             self._jsonData['repl-config'] = {}
 
         # Clear out the file so that calling 'Commit' will re-open the file at that time in write mode.
@@ -166,7 +165,6 @@ def Commit(self):
         ''' Commits the cached JSON configuration to file (if one was provided in the constructor).
             Otherwise, this is a no-op.
         '''
-        self.logger().info("Committing...")
 
         if (self._path is None):
             return
@@ -175,9 +173,8 @@ def Commit(self):
             try:
                 self._file = open(self._path, 'w')
             except Exception as ex:
-                logging.warn(
-                    f"Could not open {self._path} for writing configuration. Error:")
-                logging.warn(ex)
+                LOGGER.error(
+                    f"Could not open {self._path} for writing configuration. Error: {ex}")
                 return
 
         self._file.seek(0)
@@ -188,7 +185,7 @@ def Commit(self):
     def SetReplKey(self, key: str, value):
         ''' Set a REPL key to a specific value. Creates the key if one doesn't exist already.
         '''
-        self.logger().info(f"SetReplKey: {key} = {value}")
+        LOGGER.debug(f"SetReplKey: {key} = {value}")
 
         if (key is None or key == ''):
             raise ValueError("Invalid Key")
@@ -212,7 +209,7 @@ def GetReplKey(self, key: str):
     def SetSdkKey(self, key: str, value: bytes):
         ''' Set an SDK key to a specific value. Creates the key if one doesn't exist already.
         '''
-        self.logger().info(f"SetSdkKey: {key} = {value}")
+        LOGGER.debug(f"SetSdkKey: {key} = {value}")
 
         if (key is None or key == ''):
             raise ValueError("Invalid Key")
@@ -236,7 +233,7 @@ def GetSdkKey(self, key: str):
     def DeleteSdkKey(self, key: str):
         ''' Deletes an SDK key if one exists.
         '''
-        self.logger().info(f"DeleteSdkKey: {key}")
+        LOGGER.debug(f"DeleteSdkKey: {key}")
 
         del (self._jsonData['sdk-config'][key])
         self.Commit()