From b1230c9aadfbff02772ecf1710da8507837f8f94 Mon Sep 17 00:00:00 2001 From: Dirk Alders Date: Fri, 25 Dec 2020 17:01:16 +0100 Subject: [PATCH] Channel logging implemented --- __init__.py | 115 ++++++++++++++++++++++++++++++++++++++-------------- 1 file changed, 84 insertions(+), 31 deletions(-) diff --git a/__init__.py b/__init__.py index 2dba9bb..5800ffd 100644 --- a/__init__.py +++ b/__init__.py @@ -50,14 +50,19 @@ __INTERPRETER__ = (2, 3) """The Tested Interpreter-Versions""" -class RegistrationError(BaseException): - pass - - class callback_storage(dict): - def __init__(self): + DEFAULT_CHANNEL_NAME = 'all_others' + + def __init__(self, channel_name): + self.init_channel_name(channel_name) dict.__init__(self) + def init_channel_name(self, channel_name): + if channel_name is None: + self.logger = logging.getLogger(ROOT_LOGGER_NAME).getChild(__name__ + '.' + self.DEFAULT_CHANNEL_NAME) + else: + self.logger = logging.getLogger(ROOT_LOGGER_NAME).getChild(__name__ + '.' + channel_name) + def get(self, service_id, data_id): if service_id is not None and data_id is not None: try: @@ -81,8 +86,9 @@ class callback_storage(dict): return (None, None, None) def add(self, service_id, data_id, callback, *args, **kwargs): - if self.get(service_id, data_id) != (None, None, None): - raise RegistrationError("Callback for service_id (%s) and data_id (%s) already exists" % (repr(service_id), repr(data_id))) + cb_data = self.get(service_id, data_id) + if cb_data != (None, None, None): + self.logger.warning("Overwriting existing callback %s for service_id (%s) and data_id (%s) to %s!", repr(cb_data[0].__name__), repr(service_id), repr(data_id), repr(callback.__name__)) if service_id not in self: self[service_id] = {} self[service_id][data_id] = (callback, args, kwargs) @@ -137,12 +143,14 @@ class struct_json_protocol(object): .. literalinclude:: ../../socket_protocol/_examples_/socket_protocol__struct_json_protocol_client.log """ - LOG_PREFIX = 'SJP:' + DEFAULT_CHANNEL_NAME = 'all_others' SID_AUTH_SEED_REQUEST = 1 SID_AUTH_KEY_REQUEST = 2 SID_AUTH_KEY_CHECK_REQUEST = 3 SID_AUTH_KEY_CHECK_RESPONSE = 4 + SID_CHANNEL_NAME_REQUEST = 5 + SID_CHANNEL_NAME_RESPONSE = 6 SID_READ_REQUEST = 10 SID_READ_RESPONSE = 11 SID_WRITE_REQUEST = 20 @@ -153,6 +161,7 @@ class struct_json_protocol(object): SID_RESPONSE_DICT = {SID_AUTH_SEED_REQUEST: SID_AUTH_KEY_REQUEST, SID_AUTH_KEY_REQUEST: SID_AUTH_KEY_CHECK_REQUEST, SID_AUTH_KEY_CHECK_REQUEST: SID_AUTH_KEY_CHECK_RESPONSE, + SID_CHANNEL_NAME_REQUEST: SID_CHANNEL_NAME_RESPONSE, SID_READ_REQUEST: SID_READ_RESPONSE, SID_WRITE_REQUEST: SID_WRITE_RESPONSE, SID_EXECUTE_REQUEST: SID_EXECUTE_RESPONSE} @@ -183,22 +192,44 @@ class struct_json_protocol(object): AUTH_STATE_KEY_TRANSFERRED: 'Key has been sent', AUTH_STATE_TRUSTED_CLIENT: 'Trusted Client'} - def __init__(self, comm_instance, secret=None, auto_auth=False): + def __init__(self, comm_instance, secret=None, auto_auth=False, channel_name=None): + self.__comm_inst__ = comm_instance self.__secret__ = secret self.__auto_auth__ = auto_auth + # + self.__callbacks__ = callback_storage(channel_name) + self.__init_channel_name__(channel_name) + # self.__clean_receive_buffer__() - self.__callbacks__ = callback_storage() self.__callbacks__.add(self.SID_AUTH_SEED_REQUEST, 0, self.__authentificate_create_seed__) self.__callbacks__.add(self.SID_AUTH_KEY_REQUEST, 0, self.__authentificate_create_key__) self.__callbacks__.add(self.SID_AUTH_KEY_CHECK_REQUEST, 0, self.__authentificate_check_key__) self.__callbacks__.add(self.SID_AUTH_KEY_CHECK_RESPONSE, 0, self.__authentificate_process_feedback__) + self.__callbacks__.add(self.SID_CHANNEL_NAME_REQUEST, 0, self.__channel_name_request__) + self.__callbacks__.add(self.SID_CHANNEL_NAME_RESPONSE, 0, self.__channel_name_response__) self.__authentification_state_reset__() self.__seed__ = None - self.__comm_inst__ = comm_instance self.__comm_inst__.register_callback(self.__data_available_callback__) self.__comm_inst__.register_connect_callback(self.__connection_established__) self.__comm_inst__.register_disconnect_callback(self.__authentification_state_reset__) + def __init_channel_name__(self, channel_name): + self.__comm_inst__.init_channel_name(channel_name) + self.__callbacks__.init_channel_name(channel_name) + if channel_name is None: + self.logger = logging.getLogger(ROOT_LOGGER_NAME).getChild(__name__ + '.' + self.DEFAULT_CHANNEL_NAME) + else: + self.logger = logging.getLogger(ROOT_LOGGER_NAME).getChild(__name__ + '.' + channel_name) + + @property + def __channel_name__(self): + cn = self.logger.name.split('.')[-1] + if cn != self.DEFAULT_CHANNEL_NAME: + return cn + + def __log_prefix__(self): + return ' SP client:' if self.__comm_inst__.IS_CLIENT else ' SP server:' + def connected(self): return self.__comm_inst__.is_connected() @@ -210,11 +241,33 @@ class struct_json_protocol(object): def __connection_established__(self): self.__clean_receive_buffer__() + if not self.__comm_inst__.IS_CLIENT: + self.send(self.SID_CHANNEL_NAME_REQUEST, 0, self.__channel_name__) if self.__auto_auth__ and self.__comm_inst__.IS_CLIENT and self.__secret__ is not None: self.authentificate() + def __channel_name_request__(self, msg): + data = msg.get_data() + if data is None: + return self.STATUS_OKAY, self.__channel_name__ + else: + prev_channel_name = self.__channel_name__ + self.__init_channel_name__(data) + if prev_channel_name is not None and prev_channel_name != data: + self.logger.warning('%s overwriting user defined channel name from %s to %s', self.__log_prefix__(), repr(prev_channel_name), repr(data)) + elif prev_channel_name is None: + self.logger.info('%s channel name is now %s', self.__log_prefix__(), repr(self.__channel_name__)) + return self.STATUS_OKAY, None + + def __channel_name_response__(self, msg): + data = msg.get_data() + if self.__channel_name__ is None and data is not None: + self.__init_channel_name__(data) + self.logger.info('%s channel name is now %s', self.__log_prefix__(), repr(self.__channel_name__)) + return self.STATUS_OKAY, None + def __authentification_state_reset__(self): - logger.info("%s Resetting authentification state to AUTH_STATE_UNKNOWN_CLIENT", self.LOG_PREFIX) + self.logger.info("%s Resetting authentification state to AUTH_STATE_UNKNOWN_CLIENT", self.__log_prefix__()) self.__authentification_state__ = self.AUTH_STATE_UNKNOWN_CLIENT def __analyse_frame__(self, frame): @@ -253,12 +306,12 @@ class struct_json_protocol(object): def __data_available_callback__(self, comm_inst): frame = comm_inst.receive() if not self.__check_frame_checksum__(frame): - logger.warning("%s Received message has a wrong checksum and will be ignored: %s.", self.LOG_PREFIX, stringtools.hexlify(frame)) + self.logger.warning("%s Received message has a wrong checksum and will be ignored: %s.", self.__log_prefix__(), stringtools.hexlify(frame)) else: msg = self.__analyse_frame__(frame) - logger.info( + self.logger.info( '%s RX <- status: %s, service_id: %s, data_id: %s, data: "%s"', - self.LOG_PREFIX, + self.__log_prefix__(), repr(msg.get_status()), repr(msg.get_service_id()), repr(msg.get_data_id()), @@ -272,14 +325,14 @@ class struct_json_protocol(object): if self.__secret__ is not None and not self.check_authentification_state() and msg.get_service_id() not in self.SID_AUTH_LIST: status = self.STATUS_AUTH_REQUIRED data = None - logger.warning("%s Received message needs authentification: %s. Sending negative response.", self.LOG_PREFIX, self.AUTH_STATUS_NAMES.get(self.__authentification_state__, 'Unknown authentification status!')) + self.logger.warning("%s Received message needs authentification: %s. Sending negative response.", self.__log_prefix__(), self.AUTH_STATUS_NAMES.get(self.__authentification_state__, 'Unknown authentification status!')) elif callback is None: - logger.warning("%s Received message with no registered callback. Sending negative response.", self.LOG_PREFIX) + self.logger.warning("%s Received message with no registered callback. Sending negative response.", self.__log_prefix__()) status = self.STATUS_BUFFERING_UNHANDLED_REQUEST data = None else: try: - logger.debug("%s Executing callback %s to process received data", self.LOG_PREFIX, callback.__name__) + self.logger.debug("%s Executing callback %s to process received data", self.__log_prefix__(), callback.__name__) status, data = callback(msg, *args, **kwargs) except TypeError: raise TypeError('Check return value of callback function {callback_name} for service_id {service_id} and data_id {data_id}'.format(callback_name=callback.__name__, service_id=repr(msg.get_service_id()), data_id=repr(msg.get_data_id()))) @@ -289,14 +342,14 @@ class struct_json_protocol(object): # RESPONSE RECEIVED # if msg.get_status() not in [self.STATUS_OKAY]: - logger.warning("%s Received message has a peculiar status: %s", self.LOG_PREFIX, self.STATUS_NAMES.get(msg.get_status(), 'Unknown status response!')) + self.logger.warning("%s Received message has a peculiar status: %s", self.__log_prefix__(), self.STATUS_NAMES.get(msg.get_status(), 'Unknown status response!')) if callback is None: status = self.STATUS_OKAY data = None self.__buffer_received_data__(msg) else: try: - logger.debug("%s Executing callback %s to process received data", self.LOG_PREFIX, callback.__name__) + self.logger.debug("%s Executing callback %s to process received data", self.__log_prefix__(), callback.__name__) status, data = callback(msg, *args, **kwargs) except TypeError: raise TypeError('Check return value of callback function {callback_name} for service_id {service_id} and data_id {data_id}'.format(callback_name=callback.__name__, service_id=repr(msg.get_service_id()), data_id=repr(msg.get_data_id()))) @@ -307,10 +360,10 @@ class struct_json_protocol(object): if not msg.get_data_id() in self.__msg_buffer__[msg.get_service_id()]: self.__msg_buffer__[msg.get_service_id()][msg.get_data_id()] = [] self.__msg_buffer__[msg.get_service_id()][msg.get_data_id()].append(msg) - logger.debug("%s Message data is stored in buffer and is now ready to be retrieved by receive method", self.LOG_PREFIX) + self.logger.debug("%s Message data is stored in buffer and is now ready to be retrieved by receive method", self.__log_prefix__()) def __clean_receive_buffer__(self): - logger.debug("%s Cleaning up receive-buffer", self.LOG_PREFIX) + self.logger.debug("%s Cleaning up receive-buffer", self.__log_prefix__()) self.__msg_buffer__ = {} def receive(self, service_id, data_id, timeout=1): @@ -324,7 +377,7 @@ class struct_json_protocol(object): cnt += 1 time.sleep(0.1) if data is None and cnt >= timeout * 10: - logger.warning('%s TIMEOUT (%ss): Requested data (service_id: %s; data_id: %s) not in buffer.', self.LOG_PREFIX, repr(timeout), repr(service_id), repr(data_id)) + self.logger.warning('%s TIMEOUT (%ss): Requested data (service_id: %s; data_id: %s) not in buffer.', self.__log_prefix__(), repr(timeout), repr(service_id), repr(data_id)) return data def __mk_msg__(self, status, service_id, data_id, data): @@ -349,7 +402,7 @@ class struct_json_protocol(object): This methods sends out a message with the given content. """ - logger.log(log_lvl, '%s TX -> status: %d, service_id: %d, data_id: %d, data: "%s"', self.LOG_PREFIX, status, service_id, data_id, repr(data)) + self.logger.log(log_lvl, '%s TX -> status: %d, service_id: %d, data_id: %d, data: "%s"', self.__log_prefix__(), status, service_id, data_id, repr(data)) return self.__comm_inst__.send(self.__build_frame__(service_id, data_id, data, status), timeout=timeout, log_lvl=logging.DEBUG) def register_callback(self, service_id, data_id, callback, *args, **kwargs): @@ -393,7 +446,7 @@ class struct_json_protocol(object): """ if self.__secret__ is not None: self.__authentification_state__ = self.AUTH_STATE_SEED_REQUESTED - logger.info("%s Requesting seed for authentification", self.LOG_PREFIX) + self.logger.info("%s Requesting seed for authentification", self.__log_prefix__()) self.send(self.SID_AUTH_SEED_REQUEST, 0, None) cnt = 0 while cnt < timeout * 10: @@ -419,7 +472,7 @@ class struct_json_protocol(object): return hashlib.sha512(seed.encode('utf-8') + self.__secret__.encode('utf-8')).hexdigest() def __authentificate_create_seed__(self, msg): - logger.info("%s Got seed request, sending seed for authentification", self.LOG_PREFIX) + self.logger.info("%s Got seed request, sending seed for authentification", self.__log_prefix__()) self.__authentification_state__ = self.AUTH_STATE_SEED_TRANSFERRED if sys.version_info >= (3, 0): self.__seed__ = binascii.hexlify(os.urandom(32)).decode('utf-8') @@ -428,7 +481,7 @@ class struct_json_protocol(object): return self.STATUS_OKAY, self.__seed__ def __authentificate_create_key__(self, msg): - logger.info("%s Got seed, sending key for authentification", self.LOG_PREFIX) + self.logger.info("%s Got seed, sending key for authentification", self.__log_prefix__()) self.__authentification_state__ = self.AUTH_STATE_KEY_TRANSFERRED seed = msg.get_data() key = self.__authentificate_salt_and_hash__(seed) @@ -438,21 +491,21 @@ class struct_json_protocol(object): key = msg.get_data() if key == self.__authentificate_salt_and_hash__(self.__seed__): self.__authentification_state__ = self.AUTH_STATE_TRUSTED_CLIENT - logger.info("%s Got correct key, sending positive authentification feedback", self.LOG_PREFIX) + self.logger.info("%s Got correct key, sending positive authentification feedback", self.__log_prefix__()) return self.STATUS_OKAY, True else: self.__authentification_state__ = self.AUTH_STATE_UNKNOWN_CLIENT - logger.info("%s Got incorrect key, sending negative authentification feedback", self.LOG_PREFIX) + self.logger.info("%s Got incorrect key, sending negative authentification feedback", self.__log_prefix__()) return self.STATUS_OKAY, False def __authentificate_process_feedback__(self, msg): feedback = msg.get_data() if feedback: self.__authentification_state__ = self.AUTH_STATE_TRUSTED_CLIENT - logger.info("%s Got positive authentification feedback", self.LOG_PREFIX) + self.logger.info("%s Got positive authentification feedback", self.__log_prefix__()) else: self.__authentification_state__ = self.AUTH_STATE_UNKNOWN_CLIENT - logger.warning("%s Got negative authentification feedback", self.LOG_PREFIX) + self.logger.warning("%s Got negative authentification feedback", self.__log_prefix__()) return self.STATUS_OKAY, None