Faucet8021XPeriodicReauthTest flakes failing to reauth after first successful auth
anarkiwi opened this issue · 1 comments
When the re-auth fails:
Aug 17 07:44:36 faucet.Chewie INFO running job reauth_port (MacAddress.from_string("6e:5e:ec:16:ed:53"), '00:00:00:00:00:02')
Aug 17 07:44:36 faucet.Chewie INFO reauthenticating src_mac: 6e:5e:ec:16:ed:53 on port: 00:00:00:00:00:02
Aug 17 07:44:36 faucet.Chewie INFO sending premptive on port 00:00:00:00:00:02
Aug 17 07:44:36 faucet.Chewie INFO running job event (<chewie.event.EventSessionTimeout object at 0x7fbc898f5a90>,)
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO full state machine received event: <chewie.event.EventSessionTimeout object at 0x7fbc898f5a90>
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO Entering logoff2_state
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO end state: LOGOFF2
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO client is logging off 6e:5e:ec:16:ed:53
Aug 17 07:44:36 faucet INFO Logoff from MAC 6e:5e:ec:16:ed:53 on 2
Aug 17 07:44:36 faucet.Chewie INFO Sending message 'IdentityMessage': src_mac: '01:80:c2:00:00:03', id: '122', code: '1', identity: '' from 00:00:00:00:00:02 to 01:80:c2:00:00:03
Aug 17 07:44:36 faucet.Chewie INFO Received packed_message: b'\x00\x00\x00\x00\x00\x02n^\xec\x16\xedS\x88\x8e\x01\x00\x00\t\x02z\x00\t\x01user'
Aug 17 07:44:36 faucet.Chewie INFO Received eap message: 'IdentityMessage': src_mac: '6e:5e:ec:16:ed:53', id: '122', code: '2', identity: 'user'
Aug 17 07:44:36 faucet.Chewie INFO eap EAP(): 'IdentityMessage': src_mac: '6e:5e:ec:16:ed:53', id: '122', code: '2', identity: 'user'
Aug 17 07:44:36 faucet.Chewie INFO Port based state machines are as follows: {'6e:5e:ec:16:ed:53': <chewie.state_machines.eap_state_machine.FullEAPStateMachine object at 0x7fbc8647add8>}
Aug 17 07:44:36 faucet.Chewie DEBUG eap packet is response to chewie initiated authentication
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO full state machine received event: EventPreemptiveEAPResponseMessageReceived("'IdentityMessage': src_mac: '6e:5e:ec:16:ed:53', id: '122', code: '2', identity: 'user'", "00:00:00:00:00:02")
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO type: <class 'chewie.message_parser.IdentityMessage'>, message 'IdentityMessage': src_mac: '6e:5e:ec:16:ed:53', id: '122', code: '2', identity: 'user'
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO end state: LOGOFF2
Aug 17 07:44:36 faucet.Chewie.SM - port: 00:00:00:00:00:02, client: 6e:5e:ec:16:ed:53 INFO client is logging off 6e:5e:ec:16:ed:53
Aug 17 07:44:36 faucet INFO Logoff from MAC 6e:5e:ec:16:ed:53 on 2
Versus succeeds:
Aug 17 08:03:24 faucet.Chewie INFO running job reauth_port (MacAddress.from_string("ea:20:71:08:9d:b0"), '00:00:00:00:00:05')
Aug 17 08:03:24 faucet.Chewie INFO reauthenticating src_mac: ea:20:71:08:9d:b0 on port: 00:00:00:00:00:05
Aug 17 08:03:24 faucet.Chewie INFO sending premptive on port 00:00:00:00:00:05
Aug 17 08:03:24 faucet.Chewie INFO running job event (<chewie.event.EventSessionTimeout object at 0x7fe714ef3470>,)
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO full state machine received event: <chewie.event.EventSessionTimeout object at 0x7fe714ef3470>
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO Entering logoff2_state
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO end state: LOGOFF2
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO client is logging off ea:20:71:08:9d:b0
Aug 17 08:03:24 faucet INFO Logoff from MAC ea:20:71:08:9d:b0 on 5
Aug 17 08:03:24 faucet.Chewie INFO Sending message 'IdentityMessage': src_mac: '01:80:c2:00:00:03', id: '21', code: '1', identity: '' from 00:00:00:00:00:05 to 01:80:c2:00:00:03
Aug 17 08:03:24 faucet.Chewie INFO Received packed_message: b'\x00\x00\x00\x00\x00\x05\xea q\x08\x9d\xb0\x88\x8e\x01\x00\x00\t\x02\x15\x00\t\x01user'
Aug 17 08:03:24 faucet.Chewie INFO Received eap message: 'IdentityMessage': src_mac: 'ea:20:71:08:9d:b0', id: '21', code: '2', identity: 'user'
Aug 17 08:03:24 faucet.Chewie INFO eap EAP(): 'IdentityMessage': src_mac: 'ea:20:71:08:9d:b0', id: '21', code: '2', identity: 'user'
Aug 17 08:03:24 faucet.Chewie INFO Port based state machines are as follows: {'ea:20:71:08:9d:b0': <chewie.state_machines.eap_state_machine.FullEAPStateMachine object at 0x7fe714ea3390>}
Aug 17 08:03:24 faucet.Chewie DEBUG eap packet is response to chewie initiated authentication
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO Resetting eap due to received response to preemtive request
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO full state machine received event: EventPreemptiveEAPResponseMessageReceived("'IdentityMessage': src_mac: 'ea:20:71:08:9d:b0', id: '21', code: '2', identity: 'user'", "00:00:00:00:00:05")
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO type: <class 'chewie.message_parser.IdentityMessage'>, message 'IdentityMessage': src_mac: 'ea:20:71:08:9d:b0', id: '21', code: '2', identity: 'user'
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO Entering initialize_state
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO Entering select_action_state
Aug 17 08:03:24 faucet.Chewie.SM - port: 00:00:00:00:00:05, client: ea:20:71:08:9d:b0 INFO Entering initialize_passthrough_state
chewie/state_machines/eap_state_machine.py:
# TODO remove and refactor code - Just placing here to separate main pipeline for internals of SM
if (isinstance(event, EventPreemptiveEAPResponseMessageReceived)
and event.preemptive_eap_id != self.current_id):
self.logger.info(
"Resetting eap due to received response to preemtive request")
self.eap_restart = True
self.override_current_id = event.preemptive_eap_id