Debug 802.1x port stuck "IDLE"

yaplej · ‎08-25-2010

Hello,

I have setup 802.1x and it seems to work most of the time but once in a while the port gets stuck in an IDLE state.

show dot1x int fa0/10
Supplicant MAC <Not Applicable>
AuthSM State          = CONNECTING
BendSM State          = IDLE
Posture               = N/A
   ReAuthPeriod      = None (From Authentication Server)
   ReAuthAction      = N/A
   TimeToNextReauth  = N/A
PortStatus            = UNAUTHORIZED
MaxReq                = 2
MaxAuthReq            = 2
HostMode              = Single
Port Control          = Auto
ControlDirection      = Both
QuietPeriod           = 60 Seconds
Re-authentication     = Enabled
ReAuthPeriod          = From Authentication Server
ServerTimeout         = 10 Seconds
SuppTimeout           = 10 Seconds
TxPeriod              = 10 Seconds
Guest-Vlan            = 20
AuthFail-Vlan         = 20
AuthFail-Max-Attempts = 2

I dont know what could be causing the problem so I enabled debug dot1x all to see whats going on. However I cannot figure out what the problem is. Could a bug in the NIC driver cause the port to hang in an IDLE state? Once a user logs into the system it re-authenticates and come out of the IDLE state but the system itself was not able to connect to the network.

017377: Aug 25 20:08:39.414: dot1x-sm:Fa0/8:0000.0000.0000:dot1x_process_txWhen_
expire called
017378: Aug 25 20:08:39.414: dot1x_auth Fa0/8: during state auth_connecting,
got event 19(txWhen_expire)
017379: Aug 25 20:08:39.414: @@@ dot1x_auth Fa0/8: auth_connecting -> auth_conne
cting
017380: Aug 25 20:08:39.414: dot1x-sm:Fa0/8:0000.0000.0000:auth_connecting_conne
cting_action called
017381: Aug 25 20:08:39.414: dot1x-sm:dot1x_auth_connecting_action:0000.0000.000
0 auth_count=4 exceeded max auth count=3

017382: Aug 25 20:08:39.414: dot1x-ev:dot1x_post_message_to_auth_sm: Skipping tx
for req_id for default supplicant

017383: Aug 25 20:08:46.282: dot1x-sm:Fa0/11:0000.0000.0000:dot1x_process_txWhen
_expire called
017384: Aug 25 20:08:46.282: dot1x_auth Fa0/11: during state auth_connecting
, got event 19(txWhen_expire)
017385: Aug 25 20:08:46.282: @@@ dot1x_auth Fa0/11: auth_connecting -> auth_conn
ecting
017386: Aug 25 20:08:46.282: dot1x-sm:Fa0/11:0000.0000.0000:auth_connecting_conn
ecting_action called
017387: Aug 25 20:08:46.282: dot1x-ev:dot1x_post_message_to_auth_sm: Skipping tx
for req_id for default supplicant

017388: Aug 25 20:08:48.070: dot1x-sm:Fa0/10:0000.0000.0000:dot1x_process_txWhen
_expire called
017389: Aug 25 20:08:48.070: dot1x_auth Fa0/10: during state auth_connecting
, got event 19(txWhen_expire)
017390: Aug 25 20:08:48.070: @@@ dot1x_auth Fa0/10: auth_connecting -> auth_conn
ecting
017391: Aug 25 20:08:48.070: dot1x-sm:Fa0/10:0000.0000.0000:auth_connecting_conn
ecting_action called
017392: Aug 25 20:08:48.070: dot1x-ev:dot1x_post_message_to_auth_sm: Tx for req_
id for supplicant 0000.0000.0000

017393: Aug 25 20:08:48.070: dot1x-ev:Transmitting an EAPOL frame on FastEtherne
t0/10
017394: Aug 25 20:08:48.070: dot1x-packet:Tx EAP-Request(Id), id 8, ver 1, len 5
(Fa0/10)
017395: Aug 25 20:08:48.074: dot1x-registry:registry:dot1x_ether_macaddr called
017396: Aug 25 20:08:48.074: dot1x-packet:Tx sa=0005.dcc1.52ca, da=0180.c200.000
3, et 888E (Fa0/10)
017397: Aug 25 20:08:49.414: dot1x-sm:Fa0/8:0000.0000.0000:dot1x_process_txWhen_
expire called
017398: Aug 25 20:08:49.414: dot1x_auth Fa0/8: during state auth_connecting,
got event 19(txWhen_expire)
017399: Aug 25 20:08:49.414: @@@ dot1x_auth Fa0/8: auth_connecting -> auth_conne
cting
017400: Aug 25 20:08:49.414: dot1x-sm:Fa0/8:0000.0000.0000:auth_connecting_conne
cting_action called
017401: Aug 25 20:08:49.414: dot1x-ev:dot1x_post_message_to_auth_sm: Skipping tx
for req_id for default supplicant

017402: Aug 25 20:08:56.282: dot1x-sm:Fa0/11:0000.0000.0000:dot1x_process_txWhen
_expire called
017403: Aug 25 20:08:56.282: dot1x_auth Fa0/11: during state auth_connecting
, got event 19(txWhen_expire)
017404: Aug 25 20:08:56.282: @@@ dot1x_auth Fa0/11: auth_connecting -> auth_conn
ecting
017405: Aug 25 20:08:56.282: dot1x-sm:Fa0/11:0000.0000.0000:auth_connecting_conn
ecting_action called
017406: Aug 25 20:08:56.282: dot1x-sm:dot1x_auth_connecting_action:0000.0000.000
0 auth_count=4 exceeded max auth count=3

017407: Aug 25 20:08:56.282: dot1x-ev:dot1x_post_message_to_auth_sm: Skipping tx
for req_id for default supplicant

017408: Aug 25 20:08:58.070: dot1x-sm:Fa0/10:0000.0000.0000:dot1x_process_txWhen
_expire called
017409: Aug 25 20:08:58.070: dot1x_auth Fa0/10: during state auth_connecting
, got event 19(txWhen_expire)
017410: Aug 25 20:08:58.070: @@@ dot1x_auth Fa0/10: auth_connecting -> auth_conn
ecting
017411: Aug 25 20:08:58.070: dot1x-sm:Fa0/10:0000.0000.0000:auth_connecting_conn
ecting_action called
017412: Aug 25 20:08:58.070: dot1x-ev:dot1x_post_message_to_auth_sm: Tx for req_
id for supplicant 0000.0000.0000

017413: Aug 25 20:08:58.070: dot1x-ev:Transmitting an EAPOL frame on FastEtherne
t0/10
017414: Aug 25 20:08:58.074: dot1x-packet:Tx EAP-Request(Id), id 8, ver 1, len 5
(Fa0/10)
017415: Aug 25 20:08:58.074: dot1x-registry:registry:dot1x_ether_macaddr called
017416: Aug 25 20:08:58.074: dot1x-packet:Tx sa=0005.dcc1.52ca, da=0180.c200.000
3, et 888E (Fa0/10)no
017417: Aug 25 20:08:59.414: dot1x-sm:Fa0/8:0000.0000.0000:dot1x_process_txWhen_
expire called
017418: Aug 25 20:08:59.414: dot1x_auth Fa0/8: during state auth_connecting,
got event 19(txWhen_expire)
017419: Aug 25 20:08:59.414: @@@ dot1x_auth Fa0/8: auth_connecting -> auth_conne
cting
017420: Aug 25 20:08:59.414: dot1x-sm:Fa0/8:0000.0000.0000:auth_connecting_conne
cting_action called
017421: Aug 25 20:08:59.414: dot1x-ev:dot1x_post_message_to_auth_sm: Skipping tx
for req_id for default supplicant

yaplej · ‎08-30-2010

Anyone else seen this with Broadcom NICs? I am thinking its a bug in the driver but am not 100% sure of that. I can turn the system off for a moment and then it works fine.

Just wanted to see if anyone else had seen this or could tell from the debug if its some other issue.

Thanks.