pylib/socket_protocol
1
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity

Channel logging implemented

Browse Source
This commit is contained in:
Dirk Alders 2020-12-25 17:01:16 +01:00
parent 8a8522d26b
commit b1230c9aad
1 changed files with 84 additions and 31 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

115
__init__.py
View File

@ -50,14 +50,19 @@ __INTERPRETER__ = (2, 3)
"""The Tested Interpreter-Versions""" """The Tested Interpreter-Versions"""
class RegistrationError(BaseException):
pass
class callback_storage(dict): 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) 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): def get(self, service_id, data_id):
if service_id is not None and data_id is not None: if service_id is not None and data_id is not None:
try: try:
@ -81,8 +86,9 @@ class callback_storage(dict):
return (None, None, None) return (None, None, None)
def add(self, service_id, data_id, callback, *args, **kwargs): def add(self, service_id, data_id, callback, *args, **kwargs):
if self.get(service_id, data_id) != (None, None, None): cb_data = self.get(service_id, data_id)
raise RegistrationError("Callback for service_id (%s) and data_id (%s) already exists" % (repr(service_id), repr(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: if service_id not in self:
self[service_id] = {} self[service_id] = {}
self[service_id][data_id] = (callback, args, kwargs) 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 .. 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_SEED_REQUEST = 1
SID_AUTH_KEY_REQUEST = 2 SID_AUTH_KEY_REQUEST = 2
SID_AUTH_KEY_CHECK_REQUEST = 3 SID_AUTH_KEY_CHECK_REQUEST = 3
SID_AUTH_KEY_CHECK_RESPONSE = 4 SID_AUTH_KEY_CHECK_RESPONSE = 4
SID_CHANNEL_NAME_REQUEST = 5
SID_CHANNEL_NAME_RESPONSE = 6
SID_READ_REQUEST = 10 SID_READ_REQUEST = 10
SID_READ_RESPONSE = 11 SID_READ_RESPONSE = 11
SID_WRITE_REQUEST = 20 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_RESPONSE_DICT = {SID_AUTH_SEED_REQUEST: SID_AUTH_KEY_REQUEST,
SID_AUTH_KEY_REQUEST: SID_AUTH_KEY_CHECK_REQUEST, SID_AUTH_KEY_REQUEST: SID_AUTH_KEY_CHECK_REQUEST,
SID_AUTH_KEY_CHECK_REQUEST: SID_AUTH_KEY_CHECK_RESPONSE, 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_READ_REQUEST: SID_READ_RESPONSE,
SID_WRITE_REQUEST: SID_WRITE_RESPONSE, SID_WRITE_REQUEST: SID_WRITE_RESPONSE,
SID_EXECUTE_REQUEST: SID_EXECUTE_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_KEY_TRANSFERRED: 'Key has been sent',
AUTH_STATE_TRUSTED_CLIENT: 'Trusted Client'} 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.__secret__ = secret
self.__auto_auth__ = auto_auth self.__auto_auth__ = auto_auth
#
self.__callbacks__ = callback_storage(channel_name)
self.__init_channel_name__(channel_name)
#
self.__clean_receive_buffer__() 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_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_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_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_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.__authentification_state_reset__()
self.__seed__ = None self.__seed__ = None
self.__comm_inst__ = comm_instance
self.__comm_inst__.register_callback(self.__data_available_callback__) self.__comm_inst__.register_callback(self.__data_available_callback__)
self.__comm_inst__.register_connect_callback(self.__connection_established__) self.__comm_inst__.register_connect_callback(self.__connection_established__)
self.__comm_inst__.register_disconnect_callback(self.__authentification_state_reset__) 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): def connected(self):
return self.__comm_inst__.is_connected() return self.__comm_inst__.is_connected()
@ -210,11 +241,33 @@ class struct_json_protocol(object):
def __connection_established__(self): def __connection_established__(self):
self.__clean_receive_buffer__() 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: if self.__auto_auth__ and self.__comm_inst__.IS_CLIENT and self.__secret__ is not None:
self.authentificate() 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): 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 self.__authentification_state__ = self.AUTH_STATE_UNKNOWN_CLIENT
def __analyse_frame__(self, frame): def __analyse_frame__(self, frame):
@ -253,12 +306,12 @@ class struct_json_protocol(object):
def __data_available_callback__(self, comm_inst): def __data_available_callback__(self, comm_inst):
frame = comm_inst.receive() frame = comm_inst.receive()
if not self.__check_frame_checksum__(frame): 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: else:
msg = self.__analyse_frame__(frame) msg = self.__analyse_frame__(frame)
logger.info( self.logger.info(
'%s RX <- status: %s, service_id: %s, data_id: %s, data: "%s"', '%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_status()),
repr(msg.get_service_id()), repr(msg.get_service_id()),
repr(msg.get_data_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: 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 status = self.STATUS_AUTH_REQUIRED
data = None 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: 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 status = self.STATUS_BUFFERING_UNHANDLED_REQUEST
data = None data = None
else: else:
try: 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) status, data = callback(msg, *args, **kwargs)
except TypeError: 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()))) 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 # RESPONSE RECEIVED
# #
if msg.get_status() not in [self.STATUS_OKAY]: 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: if callback is None:
status = self.STATUS_OKAY status = self.STATUS_OKAY
data = None data = None
self.__buffer_received_data__(msg) self.__buffer_received_data__(msg)
else: else:
try: 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) status, data = callback(msg, *args, **kwargs)
except TypeError: 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()))) 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()]: 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()] = []
self.__msg_buffer__[msg.get_service_id()][msg.get_data_id()].append(msg) 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): 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__ = {} self.__msg_buffer__ = {}
def receive(self, service_id, data_id, timeout=1): def receive(self, service_id, data_id, timeout=1):
@ -324,7 +377,7 @@ class struct_json_protocol(object):
cnt += 1 cnt += 1
time.sleep(0.1) time.sleep(0.1)
if data is None and cnt >= timeout * 10: 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 return data
def __mk_msg__(self, status, service_id, data_id, 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. 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) 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): 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: if self.__secret__ is not None:
self.__authentification_state__ = self.AUTH_STATE_SEED_REQUESTED 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) self.send(self.SID_AUTH_SEED_REQUEST, 0, None)
cnt = 0 cnt = 0
while cnt < timeout * 10: 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() return hashlib.sha512(seed.encode('utf-8') + self.__secret__.encode('utf-8')).hexdigest()
def __authentificate_create_seed__(self, msg): 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 self.__authentification_state__ = self.AUTH_STATE_SEED_TRANSFERRED
if sys.version_info >= (3, 0): if sys.version_info >= (3, 0):
self.__seed__ = binascii.hexlify(os.urandom(32)).decode('utf-8') 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__ return self.STATUS_OKAY, self.__seed__
def __authentificate_create_key__(self, msg): 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 self.__authentification_state__ = self.AUTH_STATE_KEY_TRANSFERRED
seed = msg.get_data() seed = msg.get_data()
key = self.__authentificate_salt_and_hash__(seed) key = self.__authentificate_salt_and_hash__(seed)
@ -438,21 +491,21 @@ class struct_json_protocol(object):
key = msg.get_data() key = msg.get_data()
if key == self.__authentificate_salt_and_hash__(self.__seed__): if key == self.__authentificate_salt_and_hash__(self.__seed__):
self.__authentification_state__ = self.AUTH_STATE_TRUSTED_CLIENT 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 return self.STATUS_OKAY, True
else: else:
self.__authentification_state__ = self.AUTH_STATE_UNKNOWN_CLIENT 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 return self.STATUS_OKAY, False
def __authentificate_process_feedback__(self, msg): def __authentificate_process_feedback__(self, msg):
feedback = msg.get_data() feedback = msg.get_data()
if feedback: if feedback:
self.__authentification_state__ = self.AUTH_STATE_TRUSTED_CLIENT 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: else:
self.__authentification_state__ = self.AUTH_STATE_UNKNOWN_CLIENT 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 return self.STATUS_OKAY, None