From 876d802b0691717b2a1028aa69037cae0d02d9b2 Mon Sep 17 00:00:00 2001 From: Stefan Agner Date: Tue, 16 Jul 2024 09:51:49 +0200 Subject: [PATCH] [Python] Adjust logging levels in Python controller 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. --- .../python/chip/CertificateAuthority.py | 8 +++-- src/controller/python/chip/ChipDeviceCtrl.py | 33 ++++++++++--------- src/controller/python/chip/FabricAdmin.py | 10 +++--- .../python/chip/clusters/Attribute.py | 19 ++++++----- .../python/chip/storage/__init__.py | 31 ++++++++--------- 5 files changed, 50 insertions(+), 51 deletions(-) diff --git a/src/controller/python/chip/CertificateAuthority.py b/src/controller/python/chip/CertificateAuthority.py index bce921cfb785bf..0fbfcfdbdb93b8 100644 --- a/src/controller/python/chip/CertificateAuthority.py +++ b/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). diff --git a/src/controller/python/chip/ChipDeviceCtrl.py b/src/controller/python/chip/ChipDeviceCtrl.py index efadd7fd4f87c7..d9c9196015c96d 100644 --- a/src/controller/python/chip/ChipDeviceCtrl.py +++ b/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,9 +403,9 @@ 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) @@ -411,7 +413,7 @@ def HandleCommissioningComplete(nodeId: int, err: PyChipError): 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 diff --git a/src/controller/python/chip/FabricAdmin.py b/src/controller/python/chip/FabricAdmin.py index fc20327e628bcc..d9e2e35cb2bcc4 100644 --- a/src/controller/python/chip/FabricAdmin.py +++ b/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}") diff --git a/src/controller/python/chip/clusters/Attribute.py b/src/controller/python/chip/clusters/Attribute.py index 36f5a794f9e73e..ba4c5d4b72dbe6 100644 --- a/src/controller/python/chip/clusters/Attribute.py +++ b/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 diff --git a/src/controller/python/chip/storage/__init__.py b/src/controller/python/chip/storage/__init__.py index 385efca6be1c8c..20432dcd01870b 100644 --- a/src/controller/python/chip/storage/__init__.py +++ b/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()