From 907fed32ef066d76e1f667d8d3501f14b3139006 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Thu, 21 Feb 2019 16:01:35 +1300 Subject: [PATCH 01/12] send preemptive identity request on port up --- chewie/chewie.py | 56 +++++++++++++++++++++++++++++++++++++++++---- test/test_chewie.py | 38 +++++++++++++++++++++++++++++- 2 files changed, 89 insertions(+), 5 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 8427c36d..2a18f72c 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -1,6 +1,10 @@ """Entry point for 802.1X speaker. """ +import random +from chewie.eap import Eap + +from chewie.mac_address import MacAddress from eventlet import sleep, GreenPool from eventlet.queue import Queue @@ -9,9 +13,9 @@ from chewie.radius_socket import RadiusSocket from chewie.eap_state_machine import FullEAPStateMachine from chewie.radius_lifecycle import RadiusLifecycle -from chewie.message_parser import MessageParser, MessagePacker +from chewie.message_parser import MessageParser, MessagePacker, IdentityMessage from chewie.event import EventMessageReceived, EventPortStatusChange -from chewie.utils import get_logger, MessageParseError +from chewie.utils import get_logger, MessageParseError, EapQueueMessage def unpack_byte_string(byte_string): @@ -19,9 +23,16 @@ def unpack_byte_string(byte_string): return "".join("%02x" % x for x in byte_string) +def get_random_id(): + return random.randint(0, 200) + + class Chewie: """Facilitates EAP supplicant and RADIUS server communication""" RADIUS_UDP_PORT = 1812 + PAE_GROUP_ADDRESS = MacAddress.from_string("01:80:C2:00:00:03") + + DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL = 60 def __init__(self, interface_name, logger=None, auth_handler=None, failure_handler=None, logoff_handler=None, @@ -46,7 +57,8 @@ def __init__(self, interface_name, logger=None, if chewie_id: self.chewie_id = chewie_id - self.state_machines = {} # mac: state_machine + self.state_machines = {} # port_id_str: { mac : state_machine} + self.port_to_eapol_id = {} # port_id: last ID used in preemptive identity request. self.eap_output_messages = Queue() self.radius_output_messages = Queue() @@ -127,6 +139,7 @@ def port_down(self, port_id): # all chewie needs to do is change its internal state. # faucet will remove the acls by itself. self.set_port_status(port_id, False) + self.port_to_eapol_id.pop(port_id, None) def port_up(self, port_id): """ @@ -135,7 +148,42 @@ def port_up(self, port_id): port_id (str): id of port. """ self.set_port_status(port_id, True) - # TODO send preemptive identity request. + + self.send_preemptive_identity_request(port_id) + self.timer_scheduler.call_later(self.DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL, + self.send_preemptive_identity_request_if_no_active_on_port, + port_id) + + def send_preemptive_identity_request_if_no_active_on_port(self, port_id): + """ + If there is no active (in progress, or in state success(2)) supplicant send out the + preemptive identity request message. + Args: + port_id (str): + """ + state_machines = self.state_machines.get(port_id, []) + for sm in state_machines.values(): + if sm.state not in [FullEAPStateMachine.LOGOFF, FullEAPStateMachine.LOGOFF2, + FullEAPStateMachine.DISABLED, FullEAPStateMachine.NO_STATE, + FullEAPStateMachine.FAILURE, FullEAPStateMachine.FAILURE2, + FullEAPStateMachine.TIMEOUT_FAILURE, + FullEAPStateMachine.TIMEOUT_FAILURE2]: + break + else: + self.send_preemptive_identity_request(port_id) + + def send_preemptive_identity_request(self, port_id): + """ + Message (EAP Identity Request) that notifies supplicant that port is using 802.1X + Args: + port_id (str): + + """ + _id = get_random_id() + data = IdentityMessage(self.PAE_GROUP_ADDRESS, _id, Eap.REQUEST, "") + self.port_to_eapol_id[port_id] = _id + self.eap_output_messages.put_nowait( + EapQueueMessage(data, self.PAE_GROUP_ADDRESS, MacAddress.from_string(port_id))) def set_port_status(self, port_id, status): port_id_str = str(port_id) diff --git a/test/test_chewie.py b/test/test_chewie.py index 7bcccfd9..423ae3b6 100644 --- a/test/test_chewie.py +++ b/test/test_chewie.py @@ -24,6 +24,7 @@ def patch_things(func): """decorator to mock patch socket operations and random number generators""" + @patch('chewie.chewie.get_random_id', get_random_id_helper) @patch('chewie.chewie.EapSocket', FakeEapSocket) @patch('chewie.chewie.RadiusSocket', FakeRadiusSocket) @patch('chewie.chewie.RadiusLifecycle.generate_request_authenticator', urandom_helper) @@ -41,15 +42,30 @@ def wrapper_setup_gen(self): global SUPPLICANT_REPLY_GENERATOR # pylint: disable=global-statement global RADIUS_REPLY_GENERATOR # pylint: disable=global-statement global URANDOM_GENERATOR # pylint: disable=global-statement + global GET_RANDOM_ID_GENERATOR SUPPLICANT_REPLY_GENERATOR = supplicant_replies_gen(_supplicant_replies) RADIUS_REPLY_GENERATOR = radius_replies_gen(_radius_replies) URANDOM_GENERATOR = urandom() + GET_RANDOM_ID_GENERATOR = fake_get_random_id() func(self) return wrapper_setup_gen return decorator_setup_gen +def fake_get_random_id(): + for i in [103, 0x99]: + yield i + + +GET_RANDOM_ID_GENERATOR = None + + +def get_random_id_helper(): # pylint: disable=unused-argument + """helper for urandom_generator""" + return next(GET_RANDOM_ID_GENERATOR) + + def supplicant_replies_gen(replies): """generator for packets supplicant sends""" for reply in replies: @@ -285,17 +301,37 @@ def test_success_dot1x(self): '00:00:00:00:00:01').state, FullEAPStateMachine.SUCCESS2) + @patch_things def test_port_status_changes(self): """test port status api""" # TODO what can actually be checked here? # the state machine tests already check the statemachine # could check that the preemptive identity request packet is sent. (once implemented) # for now just check api works under python version. - + global TO_SUPPLICANT + pool = eventlet.GreenPool() + pool.spawn(self.chewie.run) + eventlet.sleep(1) self.chewie.port_down("00:00:00:00:00:01") self.chewie.port_up("00:00:00:00:00:01") + # check preemptive sent directly after port up + out_packet = TO_SUPPLICANT.get() + self.assertEqual(out_packet, + bytes.fromhex('0180C2000003000000000001888e010000050167000501')) + + self.assertTrue(TO_SUPPLICANT.empty()) + + while not self.fake_scheduler.jobs: + eventlet.sleep(0.1) + self.fake_scheduler.run_jobs() + eventlet.sleep(0.1) + # check preemptive sent after + out_packet = TO_SUPPLICANT.get_nowait() + self.assertEqual(out_packet, + bytes.fromhex('0180C2000003000000000001888e010000050199000501')) + self.chewie.port_down("00:00:00:00:00:01") @patch_things From adf429ba0929db3a2a32f3de79129f981498af59 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Mon, 25 Feb 2019 10:41:28 +1300 Subject: [PATCH 02/12] id request --- chewie/chewie.py | 30 +++++++++++++++++++++++++++--- chewie/timer_scheduler.py | 2 ++ 2 files changed, 29 insertions(+), 3 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 2a18f72c..615c38ad 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -59,6 +59,8 @@ def __init__(self, interface_name, logger=None, self.state_machines = {} # port_id_str: { mac : state_machine} self.port_to_eapol_id = {} # port_id: last ID used in preemptive identity request. + self.port_status = {} # port_id: status (true=up, false=down) + self.port_to_identity_job = {} # port_id: timerJob self.eap_output_messages = Queue() self.radius_output_messages = Queue() @@ -139,6 +141,10 @@ def port_down(self, port_id): # all chewie needs to do is change its internal state. # faucet will remove the acls by itself. self.set_port_status(port_id, False) + + job = self.port_to_identity_job.get(port_id, None) + if job: + job.cancel() self.port_to_eapol_id.pop(port_id, None) def port_up(self, port_id): @@ -147,12 +153,14 @@ def port_up(self, port_id): Args: port_id (str): id of port. """ + self.logger.warning("port %s up", port_id) self.set_port_status(port_id, True) self.send_preemptive_identity_request(port_id) - self.timer_scheduler.call_later(self.DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL, - self.send_preemptive_identity_request_if_no_active_on_port, - port_id) + self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( + self.DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL, + self.send_preemptive_identity_request_if_no_active_on_port, + port_id) def send_preemptive_identity_request_if_no_active_on_port(self, port_id): """ @@ -161,6 +169,16 @@ def send_preemptive_identity_request_if_no_active_on_port(self, port_id): Args: port_id (str): """ + self.logger.warning("thinking about executing timer preemptive on port %s", port_id) + # schedule next request. + self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( + self.DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL, + self.send_preemptive_identity_request_if_no_active_on_port, + port_id) + if not self.port_status.get(port_id, False): + self.logger.warning('cant send output on port %s is down', port_id) + return + state_machines = self.state_machines.get(port_id, []) for sm in state_machines.values(): if sm.state not in [FullEAPStateMachine.LOGOFF, FullEAPStateMachine.LOGOFF2, @@ -168,8 +186,10 @@ def send_preemptive_identity_request_if_no_active_on_port(self, port_id): FullEAPStateMachine.FAILURE, FullEAPStateMachine.FAILURE2, FullEAPStateMachine.TIMEOUT_FAILURE, FullEAPStateMachine.TIMEOUT_FAILURE2]: + self.logger.warning('port is active not sending on port %s', port_id) break else: + self.logger.warning("executing timer premptive on port %s", port_id) self.send_preemptive_identity_request(port_id) def send_preemptive_identity_request(self, port_id): @@ -184,9 +204,13 @@ def send_preemptive_identity_request(self, port_id): self.port_to_eapol_id[port_id] = _id self.eap_output_messages.put_nowait( EapQueueMessage(data, self.PAE_GROUP_ADDRESS, MacAddress.from_string(port_id))) + self.logger.warning("sending premptive on port %s", port_id) def set_port_status(self, port_id, status): port_id_str = str(port_id) + + self.port_status[port_id] = status + if port_id_str not in self.state_machines: self.state_machines[port_id_str] = {} diff --git a/chewie/timer_scheduler.py b/chewie/timer_scheduler.py index 3150444e..2ec97ef5 100644 --- a/chewie/timer_scheduler.py +++ b/chewie/timer_scheduler.py @@ -61,6 +61,7 @@ def call_later(self, timeout, func, *args): """ if not args: args = [] + self.logger.warning("submitted job %s %s", func.__name__, args) expiry_time = time.time() + timeout job = TimerJob(expiry_time, func, args) @@ -85,3 +86,4 @@ def run(self): self.sleep(1) except Exception as e: self.logger.exception(e) + self.logger.warning('timer_scheduler finished quuee') From 72a1cc0454acbdd99df77564b6a0491c4d7cc30a Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Thu, 14 Mar 2019 16:19:44 +1300 Subject: [PATCH 03/12] send (delayed by 20 seconds) identity request on port up. --- chewie/chewie.py | 15 +++++++++++---- chewie/eap_state_machine.py | 8 ++++++++ 2 files changed, 19 insertions(+), 4 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 615c38ad..96747e26 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -32,6 +32,7 @@ class Chewie: RADIUS_UDP_PORT = 1812 PAE_GROUP_ADDRESS = MacAddress.from_string("01:80:C2:00:00:03") + DEFAULT_PORT_UP_IDENTITY_REQUEST_WAIT_PERIOD = 20 DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL = 60 def __init__(self, interface_name, logger=None, @@ -156,9 +157,8 @@ def port_up(self, port_id): self.logger.warning("port %s up", port_id) self.set_port_status(port_id, True) - self.send_preemptive_identity_request(port_id) self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( - self.DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL, + self.DEFAULT_PORT_UP_IDENTITY_REQUEST_WAIT_PERIOD, self.send_preemptive_identity_request_if_no_active_on_port, port_id) @@ -265,7 +265,8 @@ def receive_eap_messages(self): def send_eap_to_state_machine(self, eap, dst_mac): """sends an eap message to the state machine""" self.logger.info("eap EAP(): %s", eap) - state_machine = self.get_state_machine(eap.src_mac, dst_mac) + message_id = getattr(eap, 'message_id', -1) + state_machine = self.get_state_machine(eap.src_mac, dst_mac, message_id) event = EventMessageReceived(eap, dst_mac) state_machine.event(event) @@ -313,9 +314,10 @@ def get_state_machine_from_radius_packet_id(self, packet_id): """ return self.get_state_machine(**self.radius_lifecycle.packet_id_to_mac[packet_id]) - def get_state_machine(self, src_mac, port_id): + def get_state_machine(self, src_mac, port_id, message_id=-1): """Gets or creates if it does not already exist an FullEAPStateMachine for the src_mac. Args: + message_id (int): eap message id, -1 means none found. src_mac (MacAddress): who's to get. port_id (MacAddress): ID of the port where the src_mac is. @@ -336,4 +338,9 @@ def get_state_machine(self, src_mac, port_id): # TODO what if port is not actually enabled, but then how did they auth? state_machine.port_enabled = True self.state_machines[port_id_str][src_mac_str] = state_machine + else: + if message_id != -1 and message_id == self.port_to_eapol_id.get(port_id_str, -2): + self.logger.info('eap packet is response to chewie initiated authentication') + state_machine.eap_restart = True + state_machine.override_current_id = message_id return state_machine diff --git a/chewie/eap_state_machine.py b/chewie/eap_state_machine.py index 7e13df33..d336f5a9 100644 --- a/chewie/eap_state_machine.py +++ b/chewie/eap_state_machine.py @@ -295,6 +295,8 @@ class FullEAPStateMachine: last_req_data = None # EAP packet method_timeout = None # integer logoff = None # bool + # Non RFC 4137 + override_current_id = None # Lower Later to Stand-Alone Authenticator eap_resp = None # bool @@ -517,6 +519,9 @@ def success_state(self): def initialize_state(self): """Initializes variables when the state machine is activated""" self.current_id = None + if self.override_current_id: + self.current_id = self.override_current_id + self.override_current_id = None self.eap_success = False self.eap_fail = False self.eap_timeout = False @@ -781,6 +786,9 @@ def handle_success(self): self.logger.info('Yay authentication successful %s %s', self.src_mac, self.aaa_identity.identity) self.auth_handler(self.src_mac, str(self.port_id_mac)) + + self.aaa_eap_resp_data = None + # new authentication so cancel the old session timeout event if self.session_timeout_job: self.session_timeout_job.cancel() From d12cfc3187a2156fe5be0cc7e978183dda1955ac Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Mon, 18 Mar 2019 12:52:07 +1300 Subject: [PATCH 04/12] periodic reauth (currently 40 seconds). should probably increase --- chewie/chewie.py | 46 +++++++++++++++++++++++++++++-------- chewie/eap_state_machine.py | 11 +++++++++ 2 files changed, 48 insertions(+), 9 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 96747e26..238c411f 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -27,6 +27,17 @@ def get_random_id(): return random.randint(0, 200) +def log_exception(func): + def decorator_log(*args, **kwargs): + logger = args[0].logger + try: + func(*args, **kwargs) + except Exception as e: + logger.exception(e) + + return decorator_log + + class Chewie: """Facilitates EAP supplicant and RADIUS server communication""" RADIUS_UDP_PORT = 1812 @@ -40,7 +51,8 @@ def __init__(self, interface_name, logger=None, radius_server_ip=None, radius_server_port=None, radius_server_secret=None, chewie_id=None): self.interface_name = interface_name - self.logger = get_logger(logger.name + "." + Chewie.__name__) + self.log_name = logger.name + "." + Chewie.__name__ + self.logger = get_logger(self.log_name) self.auth_handler = auth_handler self.failure_handler = failure_handler self.logoff_handler = logoff_handler @@ -115,6 +127,11 @@ def auth_success(self, src_mac, port_id): if self.auth_handler: self.auth_handler(src_mac, port_id) + self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( + 40, + self.reauth_port, src_mac, + port_id) + def auth_failure(self, src_mac, port_id): """failure shim between faucet and chewie Args: @@ -159,7 +176,7 @@ def port_up(self, port_id): self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( self.DEFAULT_PORT_UP_IDENTITY_REQUEST_WAIT_PERIOD, - self.send_preemptive_identity_request_if_no_active_on_port, + self.send_preemptive_identity_request, port_id) def send_preemptive_identity_request_if_no_active_on_port(self, port_id): @@ -179,13 +196,9 @@ def send_preemptive_identity_request_if_no_active_on_port(self, port_id): self.logger.warning('cant send output on port %s is down', port_id) return - state_machines = self.state_machines.get(port_id, []) + state_machines = self.state_machines.get(port_id, {}) for sm in state_machines.values(): - if sm.state not in [FullEAPStateMachine.LOGOFF, FullEAPStateMachine.LOGOFF2, - FullEAPStateMachine.DISABLED, FullEAPStateMachine.NO_STATE, - FullEAPStateMachine.FAILURE, FullEAPStateMachine.FAILURE2, - FullEAPStateMachine.TIMEOUT_FAILURE, - FullEAPStateMachine.TIMEOUT_FAILURE2]: + if sm.is_in_progress() or sm.is_success(): self.logger.warning('port is active not sending on port %s', port_id) break else: @@ -206,6 +219,18 @@ def send_preemptive_identity_request(self, port_id): EapQueueMessage(data, self.PAE_GROUP_ADDRESS, MacAddress.from_string(port_id))) self.logger.warning("sending premptive on port %s", port_id) + def reauth_port(self, src_mac, port_id): + state_machine = self.state_machines.get(port_id, {}).get(str(src_mac), None) + + if state_machine and state_machine.is_success(): + self.logger.info('reauthenticating src_mac: %s on port: %s', src_mac, port_id) + self.send_preemptive_identity_request(port_id) + elif state_machine is None: + self.logger.info('not reauthing. state machine on port: %s, mac: %s is none', port_id, src_mac) + else: + self.logger.info("not reauthing, authentication is not in success(2) (state: %s)'", + state_machine.state) + def set_port_status(self, port_id, status): port_id_str = str(port_id) @@ -230,7 +255,7 @@ def setup_radius_socket(self): self.radius_socket.setup() self.logger.info("Radius Listening on %s:%d" % (self.radius_listen_ip, self.radius_listen_port)) - + @log_exception def send_eap_messages(self): """send eap messages to supplicant forever.""" while self.running(): @@ -243,6 +268,7 @@ def send_eap_messages(self): eap_queue_message.port_mac, eap_queue_message.src_mac)) + @log_exception def receive_eap_messages(self): """receive eap messages from supplicant forever.""" while self.running(): @@ -270,6 +296,7 @@ def send_eap_to_state_machine(self, eap, dst_mac): event = EventMessageReceived(eap, dst_mac) state_machine.event(event) + @log_exception def send_radius_messages(self): """send RADIUS messages to RADIUS Server forever.""" while self.running(): @@ -279,6 +306,7 @@ def send_radius_messages(self): self.radius_socket.send(packed_message) self.logger.info("sent radius message.") + @log_exception def receive_radius_messages(self): """receive RADIUS messages from RADIUS server forever.""" while self.running(): diff --git a/chewie/eap_state_machine.py b/chewie/eap_state_machine.py index d336f5a9..94f5aa72 100644 --- a/chewie/eap_state_machine.py +++ b/chewie/eap_state_machine.py @@ -902,3 +902,14 @@ def set_timer(self): EventTimerExpired(self, self.sent_count)) # TODO could cancel the scheduled events when # they're no longer needed (i.e. response received) + + def is_in_progress(self): + return self.state not in [FullEAPStateMachine.LOGOFF, FullEAPStateMachine.LOGOFF2, + FullEAPStateMachine.DISABLED, FullEAPStateMachine.NO_STATE, + FullEAPStateMachine.FAILURE, FullEAPStateMachine.FAILURE2, + FullEAPStateMachine.TIMEOUT_FAILURE, + FullEAPStateMachine.TIMEOUT_FAILURE2,] + # FullEAPStateMachine.SUCCESS, FullEAPStateMachine.SUCCESS2] + + def is_success(self): + return self.state in [FullEAPStateMachine.SUCCESS, FullEAPStateMachine.SUCCESS2] From 2b8754f8abfb9969f19a383fd13082337880bcc7 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Mon, 18 Mar 2019 14:53:26 +1300 Subject: [PATCH 05/12] change reauth period to use session timeout value. --- chewie/chewie.py | 14 +++++++++++--- chewie/eap_state_machine.py | 2 +- 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 238c411f..c47635b4 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -119,16 +119,17 @@ def start_threads_and_wait(self): self.pool.waitall() - def auth_success(self, src_mac, port_id): + def auth_success(self, src_mac, port_id, period): """authentication shim between faucet and chewie Args: src_mac (MacAddress): the mac of the successful supplicant - port_id (MacAddress): the 'mac' identifier of what switch port the success is on""" + port_id (MacAddress): the 'mac' identifier of what switch port the success is on + period (int): time (seconds) until the session times out.""" if self.auth_handler: self.auth_handler(src_mac, port_id) self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( - 40, + period, self.reauth_port, src_mac, port_id) @@ -220,6 +221,12 @@ def send_preemptive_identity_request(self, port_id): self.logger.warning("sending premptive on port %s", port_id) def reauth_port(self, src_mac, port_id): + """ + Send an Identity Request to src_mac, on port_id. prompting the supplicant to re authenticate. + Args: + src_mac (MacAddress): + port_id (str): + """ state_machine = self.state_machines.get(port_id, {}).get(str(src_mac), None) if state_machine and state_machine.is_success(): @@ -255,6 +262,7 @@ def setup_radius_socket(self): self.radius_socket.setup() self.logger.info("Radius Listening on %s:%d" % (self.radius_listen_ip, self.radius_listen_port)) + @log_exception def send_eap_messages(self): """send eap messages to supplicant forever.""" diff --git a/chewie/eap_state_machine.py b/chewie/eap_state_machine.py index 94f5aa72..b16a4b24 100644 --- a/chewie/eap_state_machine.py +++ b/chewie/eap_state_machine.py @@ -785,7 +785,7 @@ def handle_success(self): """Notify the success callback and sets a timer event to expire this session""" self.logger.info('Yay authentication successful %s %s', self.src_mac, self.aaa_identity.identity) - self.auth_handler(self.src_mac, str(self.port_id_mac)) + self.auth_handler(self.src_mac, str(self.port_id_mac), self.session_timeout) self.aaa_eap_resp_data = None From 8ae97f7ab900ed7873e37ec9f5087ac70df89af8 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Mon, 18 Mar 2019 17:05:21 +1300 Subject: [PATCH 06/12] signature had changed --- test/test_full_state_machine.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_full_state_machine.py b/test/test_full_state_machine.py index 63604f15..048a05ce 100644 --- a/test/test_full_state_machine.py +++ b/test/test_full_state_machine.py @@ -80,7 +80,7 @@ def tearDown(self): self.assertNotIn('aaaEapResp is true. but data is false. This should never happen', log.read()) - def auth_handler(self, client_mac, port_id_mac): # pylint: disable=unused-argument + def auth_handler(self, client_mac, port_id_mac, timer): # pylint: disable=unused-argument self.auth_counter += 1 print('Successful auth from MAC %s' % str(client_mac)) From 04400cb0065fb459cd8e994dcc1f7c91222430c5 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Mon, 18 Mar 2019 17:37:20 +1300 Subject: [PATCH 07/12] skip broken test --- test/test_chewie.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/test_chewie.py b/test/test_chewie.py index 423ae3b6..e456ad4c 100644 --- a/test/test_chewie.py +++ b/test/test_chewie.py @@ -290,7 +290,7 @@ def test_get_state_machine_by_packet_id(self): def test_success_dot1x(self): """Test success api""" FROM_SUPPLICANT.put_nowait(bytes.fromhex("0000000000010242ac17006f888e01010000")) - + pool = eventlet.GreenPool() pool.spawn(self.chewie.run) @@ -301,6 +301,7 @@ def test_success_dot1x(self): '00:00:00:00:00:01').state, FullEAPStateMachine.SUCCESS2) + @unittest.skip("Test is broken.") @patch_things def test_port_status_changes(self): """test port status api""" From cfdff14037dee316b3d14485bd7c8fcaf1c77b74 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Thu, 21 Mar 2019 10:39:40 +1300 Subject: [PATCH 08/12] fix unit test for port status --- test/test_chewie.py | 24 +++++------------------- 1 file changed, 5 insertions(+), 19 deletions(-) diff --git a/test/test_chewie.py b/test/test_chewie.py index e456ad4c..9f3e831e 100644 --- a/test/test_chewie.py +++ b/test/test_chewie.py @@ -301,14 +301,10 @@ def test_success_dot1x(self): '00:00:00:00:00:01').state, FullEAPStateMachine.SUCCESS2) - @unittest.skip("Test is broken.") @patch_things def test_port_status_changes(self): - """test port status api""" - # TODO what can actually be checked here? - # the state machine tests already check the statemachine - # could check that the preemptive identity request packet is sent. (once implemented) - # for now just check api works under python version. + """test port status api and that identity request is sent after port up""" + global TO_SUPPLICANT pool = eventlet.GreenPool() pool.spawn(self.chewie.run) @@ -317,23 +313,13 @@ def test_port_status_changes(self): self.chewie.port_up("00:00:00:00:00:01") - # check preemptive sent directly after port up - out_packet = TO_SUPPLICANT.get() - self.assertEqual(out_packet, - bytes.fromhex('0180C2000003000000000001888e010000050167000501')) - - self.assertTrue(TO_SUPPLICANT.empty()) - while not self.fake_scheduler.jobs: eventlet.sleep(0.1) self.fake_scheduler.run_jobs() - eventlet.sleep(0.1) - # check preemptive sent after - out_packet = TO_SUPPLICANT.get_nowait() + # check preemptive sent directly after port up + out_packet = TO_SUPPLICANT.get() self.assertEqual(out_packet, - bytes.fromhex('0180C2000003000000000001888e010000050199000501')) - - self.chewie.port_down("00:00:00:00:00:01") + bytes.fromhex('0180C2000003000000000001888e010000050167000501')) @patch_things @setup_generators(sup_replies_logoff, radius_replies_success) From 28650bb835eaf58675544482a5bc03dc0085d258 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Thu, 21 Mar 2019 10:56:18 +1300 Subject: [PATCH 09/12] check next timerid request job is added to queue. Continously send id requests after port up if no one 'active' on port --- chewie/chewie.py | 2 +- test/helpers.py | 22 +++++++++++++++++----- test/test_chewie.py | 8 +++++++- 3 files changed, 25 insertions(+), 7 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index c47635b4..942ec95f 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -177,7 +177,7 @@ def port_up(self, port_id): self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( self.DEFAULT_PORT_UP_IDENTITY_REQUEST_WAIT_PERIOD, - self.send_preemptive_identity_request, + self.send_preemptive_identity_request_if_no_active_on_port, port_id) def send_preemptive_identity_request_if_no_active_on_port(self, port_id): diff --git a/test/helpers.py b/test/helpers.py index 43bb1cfb..c706e302 100644 --- a/test/helpers.py +++ b/test/helpers.py @@ -1,6 +1,7 @@ """Mock TimerScheduler """ + class FakeTimerJob: """Behaves like TimerJob""" def __init__(self, function, args, timeout): @@ -22,6 +23,7 @@ def run(self): if not self.is_cancelled: self.function(*self.args) + class FakeTimerScheduler: """Behaves like TimerScheduler""" def __init__(self): @@ -38,12 +40,22 @@ def call_later(self, timeout, func, *args): return job - def run_jobs(self): + def run_jobs(self, num_jobs=None): """Runs jobs in order of timeout""" - while self.jobs: - self.jobs.sort(key=lambda x: x.timeout) - job = self.jobs.pop(0) - job.run() + if not num_jobs: + while self.jobs: + self.jobs.sort(key=lambda x: x.timeout) + job = self.jobs.pop(0) + job.run() + print("ddddddddd") + else: + for _ in range(num_jobs): + if not self.jobs: + break + self.jobs.sort(key=lambda x: x.timeout) + job = self.jobs.pop(0) + job.run() + print("eeeeeeeeez") def run(self): """Clones TimerScheduler.run()""" diff --git a/test/test_chewie.py b/test/test_chewie.py index 9f3e831e..0a677a88 100644 --- a/test/test_chewie.py +++ b/test/test_chewie.py @@ -315,12 +315,18 @@ def test_port_status_changes(self): while not self.fake_scheduler.jobs: eventlet.sleep(0.1) - self.fake_scheduler.run_jobs() + self.fake_scheduler.run_jobs(num_jobs=1) # check preemptive sent directly after port up out_packet = TO_SUPPLICANT.get() self.assertEqual(out_packet, bytes.fromhex('0180C2000003000000000001888e010000050167000501')) + # check there is a new job in the queue for sending the next id request. + # This will keep adding jobs forever. + self.assertEqual(len(self.fake_scheduler.jobs), 1) + self.assertEqual(self.fake_scheduler.jobs[0].function.__name__, + Chewie.send_preemptive_identity_request_if_no_active_on_port.__name__) + @patch_things @setup_generators(sup_replies_logoff, radius_replies_success) def test_logoff_dot1x(self): From 00652f47986511ec3b17b367bd7f5b3e58a91715 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Tue, 2 Apr 2019 15:32:50 +1300 Subject: [PATCH 10/12] change log levels --- chewie/chewie.py | 45 ++++++++++++++++++++++--------------- chewie/eap_state_machine.py | 13 ++++++----- chewie/message_parser.py | 21 +++++++++++++++++ chewie/timer_scheduler.py | 4 ++-- 4 files changed, 57 insertions(+), 26 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 942ec95f..1f0a4f87 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -72,6 +72,8 @@ def __init__(self, interface_name, logger=None, self.state_machines = {} # port_id_str: { mac : state_machine} self.port_to_eapol_id = {} # port_id: last ID used in preemptive identity request. + # TODO for port_to_eapol_id - may want to set ID to null (-1...) if sent from the + # state machine. self.port_status = {} # port_id: status (true=up, false=down) self.port_to_identity_job = {} # port_id: timerJob @@ -172,7 +174,7 @@ def port_up(self, port_id): Args: port_id (str): id of port. """ - self.logger.warning("port %s up", port_id) + self.logger.info("port %s up", port_id) self.set_port_status(port_id, True) self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( @@ -187,23 +189,23 @@ def send_preemptive_identity_request_if_no_active_on_port(self, port_id): Args: port_id (str): """ - self.logger.warning("thinking about executing timer preemptive on port %s", port_id) + self.logger.debug("thinking about executing timer preemptive on port %s", port_id) # schedule next request. self.port_to_identity_job[port_id] = self.timer_scheduler.call_later( self.DEFAULT_PREEMPTIVE_IDENTITY_REQUEST_INTERVAL, self.send_preemptive_identity_request_if_no_active_on_port, port_id) if not self.port_status.get(port_id, False): - self.logger.warning('cant send output on port %s is down', port_id) + self.logger.debug('cant send output on port %s is down', port_id) return state_machines = self.state_machines.get(port_id, {}) for sm in state_machines.values(): if sm.is_in_progress() or sm.is_success(): - self.logger.warning('port is active not sending on port %s', port_id) + self.logger.debug('port is active not sending on port %s', port_id) break else: - self.logger.warning("executing timer premptive on port %s", port_id) + self.logger.debug("executing timer premptive on port %s", port_id) self.send_preemptive_identity_request(port_id) def send_preemptive_identity_request(self, port_id): @@ -218,7 +220,7 @@ def send_preemptive_identity_request(self, port_id): self.port_to_eapol_id[port_id] = _id self.eap_output_messages.put_nowait( EapQueueMessage(data, self.PAE_GROUP_ADDRESS, MacAddress.from_string(port_id))) - self.logger.warning("sending premptive on port %s", port_id) + self.logger.info("sending premptive on port %s", port_id) def reauth_port(self, src_mac, port_id): """ @@ -233,9 +235,9 @@ def reauth_port(self, src_mac, port_id): self.logger.info('reauthenticating src_mac: %s on port: %s', src_mac, port_id) self.send_preemptive_identity_request(port_id) elif state_machine is None: - self.logger.info('not reauthing. state machine on port: %s, mac: %s is none', port_id, src_mac) + self.logger.debug('not reauthing. state machine on port: %s, mac: %s is none', port_id, src_mac) else: - self.logger.info("not reauthing, authentication is not in success(2) (state: %s)'", + self.logger.debug("not reauthing, authentication is not in success(2) (state: %s)'", state_machine.state) def set_port_status(self, port_id, status): @@ -287,13 +289,14 @@ def receive_eap_messages(self): try: eap, dst_mac = MessageParser.ethernet_parse(packed_message) except MessageParseError as exception: - self.logger.info( + self.logger.warning( "MessageParser.ethernet_parse threw exception.\n" " packed_message: '%s'.\n" " exception: '%s'.", packed_message, exception) continue + self.logger.info("Received eap message: %s", str(eap)) self.send_eap_to_state_machine(eap, dst_mac) def send_eap_to_state_machine(self, eap, dst_mac): @@ -325,15 +328,15 @@ def receive_radius_messages(self): radius = MessageParser.radius_parse(packed_message, self.radius_secret, self.radius_lifecycle) except MessageParseError as exception: - self.logger.info( + self.logger.warning( "MessageParser.radius_parse threw exception.\n" " packed_message: '%s'.\n" " exception: '%s'.", packed_message, exception) continue + self.logger.info("Received RADIUS message: %s", str(radius)) self.send_radius_to_state_machine(radius) - self.logger.info("Received RADIUS message: %s", radius) def send_radius_to_state_machine(self, radius): """sends a radius message to the state machine""" @@ -367,16 +370,22 @@ def get_state_machine(self, src_mac, port_id, message_id=-1): self.state_machines[port_id_str] = {} state_machine = self.state_machines[port_id_str].get(src_mac_str, None) if not state_machine: - state_machine = FullEAPStateMachine(self.eap_output_messages, self.radius_output_messages, src_mac, + state_machine = FullEAPStateMachine(self.eap_output_messages, + self.radius_output_messages, src_mac, self.timer_scheduler, self.auth_success, - self.auth_failure, self.auth_logoff, self.logger.name) + self.auth_failure, self.auth_logoff, + self.logger.name) state_machine.eap_restart = True # TODO what if port is not actually enabled, but then how did they auth? state_machine.port_enabled = True self.state_machines[port_id_str][src_mac_str] = state_machine - else: - if message_id != -1 and message_id == self.port_to_eapol_id.get(port_id_str, -2): - self.logger.info('eap packet is response to chewie initiated authentication') - state_machine.eap_restart = True - state_machine.override_current_id = message_id + self.logger.debug("created new state machine for '%s' on port '%s'", + src_mac_str, port_id_str) + + if message_id != -1 \ + and (message_id != state_machine.current_id + and message_id == self.port_to_eapol_id.get(port_id_str, -2)): + self.logger.debug('eap packet is response to chewie initiated authentication') + state_machine.eap_restart = True + state_machine.override_current_id = message_id return state_machine diff --git a/chewie/eap_state_machine.py b/chewie/eap_state_machine.py index b16a4b24..fdb2b6db 100644 --- a/chewie/eap_state_machine.py +++ b/chewie/eap_state_machine.py @@ -11,6 +11,7 @@ from chewie.radius_attributes import SessionTimeout from chewie.utils import get_logger, log_method, RadiusQueueMessage, EapQueueMessage + class Policy: """Fleshed out enough to support passthrough mode.""" @@ -738,7 +739,7 @@ def event(self, event): if self.eap_req: if (hasattr(self.eap_req_data, 'code') and self.eap_req_data.code == Eap.REQUEST) \ or isinstance(self.eap_req_data, (SuccessMessage, FailureMessage)): - self.logger.info('outputting eap, %s %s %s', + self.logger.info("outputting eap, '%s', src: '%s' port_id: '%s'", self.eap_req_data, self.src_mac, self.port_id_mac) self.eap_output_messages.put_nowait( EapQueueMessage(self.eap_req_data, self.src_mac, self.port_id_mac)) @@ -861,18 +862,18 @@ def process_radius_message(self, event): """Process radius message (set and extract radius specific variables)""" self.eap_resp_data = None self.eap_resp = False - self.logger.info('radius attributes %s', event.attributes) + self.logger.debug('radius attributes %s', event.attributes) self.radius_state_attribute = event.state self.aaa_eap_req = True self.aaa_eap_req_data = event.message - self.logger.info('sm ev.msg: %s', self.aaa_eap_req_data) + self.logger.debug('sm ev.msg: %s', self.aaa_eap_req_data) if isinstance(self.aaa_eap_req_data, SuccessMessage): - self.logger.info("aaaSuccess") + self.logger.debug("aaaSuccess") self.aaa_success = True if isinstance(self.aaa_eap_req_data, FailureMessage): - self.logger.info("aaaFail") + self.logger.debug("aaaFail") self.aaa_fail = True - self.logger.info('radius event %s', event.__dict__) + self.logger.debug('radius event %s', event.__dict__) self.set_vars_from_radius(event.attributes) def set_vars_from_radius(self, attributes): diff --git a/chewie/message_parser.py b/chewie/message_parser.py index 4b66b754..c2cb4121 100644 --- a/chewie/message_parser.py +++ b/chewie/message_parser.py @@ -19,6 +19,12 @@ def __init__(self, src_mac, message_id): self.src_mac = src_mac self.message_id = message_id + def __str__(self): + _id = self.message_id + if not _id: + _id = -1 + return "'%s': src_mac: '%s', id: '%d'" % (self.__class__.__name__, self.src_mac, _id) + class SuccessMessage(EapMessage): @@ -40,6 +46,9 @@ def __init__(self, src_mac, message_id, code, identity): self.code = code self.identity = identity + def __str__(self): + return "%s, code: '%d', identity: '%s'" % (super().__str__(), self.code, self.identity) + @classmethod def build(cls, src_mac, eap): return cls(src_mac, eap.packet_id, eap.code, eap.identity) @@ -51,6 +60,10 @@ def __init__(self, src_mac, message_id, code, desired_auth_types): self.code = code self.desired_auth_types = desired_auth_types + def __str__(self): + return "%s, code: '%d', desired_auth_types: '%s'" \ + % (super().__str__(), self.code, self.desired_auth_types) + @classmethod def build(cls, src_mac, eap): return cls(src_mac, eap.packet_id, eap.code, eap.desired_auth_types) @@ -63,6 +76,10 @@ def __init__(self, src_mac, message_id, code, challenge, extra_data): self.challenge = challenge self.extra_data = extra_data + def __str__(self): + return "%s, code: '%d', challenge: '%s', extra_data: '%s'" \ + % (super().__str__(), self.code, self.challenge, self.extra_data) + @classmethod def build(cls, src_mac, eap): return cls(src_mac, eap.packet_id, eap.code, eap.challenge, eap.extra_data) @@ -76,6 +93,10 @@ def __init__(self, src_mac, message_id, code, flags, extra_data): self.flags = flags self.extra_data = extra_data + def __str__(self): + return "%s, code: '%d', flags: '%s', extra_data: '%s'" \ + % (super().__str__(), self.code, self.flags, self.extra_data) + @classmethod def build(cls, src_mac, eap): return cls(src_mac, eap.packet_id, eap.code, eap.flags, eap.extra_data) diff --git a/chewie/timer_scheduler.py b/chewie/timer_scheduler.py index 2ec97ef5..37c04d46 100644 --- a/chewie/timer_scheduler.py +++ b/chewie/timer_scheduler.py @@ -61,7 +61,7 @@ def call_later(self, timeout, func, *args): """ if not args: args = [] - self.logger.warning("submitted job %s %s", func.__name__, args) + self.logger.debug("submitted job %s expire in %d, args: %s", func.__name__, timeout, args) expiry_time = time.time() + timeout job = TimerJob(expiry_time, func, args) @@ -79,7 +79,7 @@ def run(self): self.logger.info('running job %s %s', job.func.__name__, job.args) job.func(*job.args) else: - self.logger.info('job %s has been cancelled', job.func.__name__) + self.logger.debug('job %s has been cancelled', job.func.__name__) else: self.sleep(1) else: From 99c2dbb9a80a7b729f1122854e9e40653a5b34b8 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Wed, 3 Apr 2019 09:50:46 +1300 Subject: [PATCH 11/12] remove exception logger (faucet will now crash and log) --- chewie/chewie.py | 15 --------------- 1 file changed, 15 deletions(-) diff --git a/chewie/chewie.py b/chewie/chewie.py index 1f0a4f87..e124b8f9 100644 --- a/chewie/chewie.py +++ b/chewie/chewie.py @@ -27,17 +27,6 @@ def get_random_id(): return random.randint(0, 200) -def log_exception(func): - def decorator_log(*args, **kwargs): - logger = args[0].logger - try: - func(*args, **kwargs) - except Exception as e: - logger.exception(e) - - return decorator_log - - class Chewie: """Facilitates EAP supplicant and RADIUS server communication""" RADIUS_UDP_PORT = 1812 @@ -265,7 +254,6 @@ def setup_radius_socket(self): self.logger.info("Radius Listening on %s:%d" % (self.radius_listen_ip, self.radius_listen_port)) - @log_exception def send_eap_messages(self): """send eap messages to supplicant forever.""" while self.running(): @@ -278,7 +266,6 @@ def send_eap_messages(self): eap_queue_message.port_mac, eap_queue_message.src_mac)) - @log_exception def receive_eap_messages(self): """receive eap messages from supplicant forever.""" while self.running(): @@ -307,7 +294,6 @@ def send_eap_to_state_machine(self, eap, dst_mac): event = EventMessageReceived(eap, dst_mac) state_machine.event(event) - @log_exception def send_radius_messages(self): """send RADIUS messages to RADIUS Server forever.""" while self.running(): @@ -317,7 +303,6 @@ def send_radius_messages(self): self.radius_socket.send(packed_message) self.logger.info("sent radius message.") - @log_exception def receive_radius_messages(self): """receive RADIUS messages from RADIUS server forever.""" while self.running(): From 415375e3e2f5cd5d328e3534f93cf9c06e4f80e9 Mon Sep 17 00:00:00 2001 From: Michael Baird Date: Wed, 3 Apr 2019 11:13:30 +1300 Subject: [PATCH 12/12] 0 is an allowed id --- chewie/message_parser.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/chewie/message_parser.py b/chewie/message_parser.py index c2cb4121..2ccbd434 100644 --- a/chewie/message_parser.py +++ b/chewie/message_parser.py @@ -21,7 +21,7 @@ def __init__(self, src_mac, message_id): def __str__(self): _id = self.message_id - if not _id: + if _id is None: _id = -1 return "'%s': src_mac: '%s', id: '%d'" % (self.__class__.__name__, self.src_mac, _id)