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()