DOT1x and CDP Bypass suddenly not working

[Justin Hale]

Hi All,

I have an issue that just presented itself out of no-where. I'm using DOT1x and have Cisco IP Phones. 

I'm using C2960-X-FPD-L switches. I have run the following port config for years.

interface GigabitEthernet1/0/37
description Standard Computer/IP Phone Port
switchport access vlan 100
switchport mode access
switchport voice vlan 200
srr-queue bandwidth share 1 50 30 20
srr-queue bandwidth shape 10 0 0 0
priority-queue out
authentication event fail action authorize vlan 801
authentication event server dead action authorize vlan 100
authentication event no-response action authorize vlan 801
authentication port-control auto
authentication periodic
no snmp trap link-status
mls qos trust dscp
dot1x pae authenticator
dot1x timeout quiet-period 10
dot1x timeout tx-period 15
spanning-tree portfast
spanning-tree bpduguard enable

All of a sudden, when phone gets disconnected by the user (which does happen at times) the phone will stop working. This is because authentication is failing and dropping into VLAN 801 (which has no access to the CallManager. Strangely this is only happening sometimes e.g. when I shut/no shut the port sometimes I get the following output (DOT1x is not initiated and everything works fine)

SWITCH(config-if)#shut
SWITCH(config-if)#no shut
SWITCH(config-if)#
Jun 17 08:13:27: dot1x-ev:[Gi1/0/37] Interface state changed to DOWN
Jun 17 08:13:27: dot1x-ev:[Gi1/0/37] Clearing all supplicant instances
SWITCH(config-if)#
Jun 17 08:13:29: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/37, changed state to down
SWITCH(config-if)#
Jun 17 08:13:29: %ILPOWER-7-DETECT: Interface Gi1/0/37: Power Device detected: IEEE PD
SWITCH(config-if)#
Jun 17 08:13:29: %ILPOWER-5-POWER_GRANTED: Interface Gi1/0/37: Power granted
Jun 17 08:13:30: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/37, changed state to down
SWITCH(config-if)#
Jun 17 08:13:32: dot1x-ev:[Gi1/0/37] Interface state changed to UP
SWITCH(config-if)#
Jun 17 08:13:34: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/37, changed state to up
Jun 17 08:13:35: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/37, changed state to up

-------------

On other times I get the following output (when DOT1x does initiate)

SWITCH(config-if)#shut
SWITCH(config-if)#
Jun 17 08:15:22: dot1x-ev:[Gi1/0/37] Interface state changed to DOWN
Jun 17 08:15:22: dot1x-ev:[Gi1/0/37] Clearing all supplicant instances
SWITCH(config-if)#
Jun 17 08:15:24: %LINK-5-CHANGED: Interface GigabitEthernet1/0/37, changed state to administratively down
Jun 17 08:15:25: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/37, changed state to down
SWITCH(config-if)#no shut
SWITCH(config-if)#
Jun 17 08:15:32: %ILPOWER-7-DETECT: Interface Gi1/0/37: Power Device detected: IEEE PD
SWITCH(config-if)#
Jun 17 08:15:33: %ILPOWER-5-POWER_GRANTED: Interface Gi1/0/37: Power granted
SWITCH(config-if)#
Jun 17 08:15:33: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/37, changed state to down
SWITCH(config-if)#
Jun 17 08:15:35: dot1x-ev:[Gi1/0/37] Interface state changed to UP
SWITCH(config-if)#
Jun 17 08:15:37: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/37, changed state to up
Jun 17 08:15:38: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/37, changed state to up
SWITCH(config-if)#
Jun 17 08:15:48: dot1x_auth Gi1/0/37: initial state auth_initialize has enter
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030: initialising
Jun 17 08:15:48: dot1x_auth Gi1/0/37: during state auth_initialize, got event 0(cfg_auto)
Jun 17 08:15:48: @@@ dot1x_auth Gi1/0/37: auth_initialize -> auth_disconnected
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030: disconnected
Jun 17 08:15:48: dot1x_auth Gi1/0/37: idle during state auth_disconnected
Jun 17 08:15:48: @@@ dot1x_auth Gi1/0/37: auth_disconnected -> auth_restart
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030: entering restart
Jun 17 08:15:48: dot1x-ev:[081f.f362.5862, Gi1/0/37] Sending create new context event to EAP for 0x25000030 (081f.f362.5862)
Jun 17 08:15:48: dot1x_auth_bend Gi1/0/37: initial state auth_bend_initialize has enter
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030: entering init state
Jun 17 08:15:48: dot1x_auth_bend Gi1/0/37: initial state auth_bend_initialize has idle
Jun 17 08:15:48: dot1x_auth_bend Gi1/0/37: during state auth_bend_initialize, got event 16383(idle)
Jun 17 08:15:48: @@@ dot1x_auth_bend Gi1/0/37: auth_bend_initialize -> auth_bend_idle
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering idle state
Jun 17 08:15:48: dot1x-ev:[081f.f362.5862, Gi1/0/37] Created a client entry (0x25000030)
Jun 17 08:15:48: dot1x-ev:[081f.f362.5862, Gi1/0/37] Dot1x authentication started for 0x25000030 (081f.f362.5862)
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting !EAP_RESTART on Client 0x25000030
Jun 17 08:15:48: dot1x_auth Gi1/0/37: during state auth_restart, got event 6(no_eapRestart)
Jun 17 08:15:48: @@@ dot1x_auth Gi1/0/37: auth_restart -> auth_connecting
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:enter connecting state
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030: restart connecting
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting RX_REQ on Client 0x25000030
Jun 17 08:15:48: dot1x_auth Gi1/0/37: during state auth_connecting, got event 10(eapReq_no_reAuthMax)
Jun 17 08:15:48: @@@ dot1x_auth Gi1/0/37: auth_connecting -> auth_authenticating
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030: authenticating state entered
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:connecting authenticating action
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting AUTH_START for 0x25000030
Jun 17 08:15:48: dot1x_auth_bend Gi1/0/37: during state auth_bend_idle, got event 4(eapReq_authStart)
Jun 17 08:15:48: @@@ dot1x_auth_bend Gi1/0/37: auth_bend_idle -> auth_bend_request
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering request state
Jun 17 08:15:48: dot1x-ev:[Gi1/0/37] Sending EAPOL packet to group PAE address
Jun 17 08:15:48: dot1x-registry:registry:dot1x_ether_macaddr called
Jun 17 08:15:48: dot1x-ev:[Gi1/0/37] Sending out EAPOL packet
Jun 17 08:15:48: dot1x-packet:EAPOL pak Tx - Ver: 0x3 type: 0x0
Jun 17 08:15:48: dot1x-packet: length: 0x0005
Jun 17 08:15:48: dot1x-packet:EAP code: 0x1 id: 0x1 length: 0x0005
Jun 17 08:15:48: dot1x-packet: type: 0x1
SWITCH(config-if)#
Jun 17 08:15:48: dot1x-packet:[081f.f362.5862, Gi1/0/37] EAPOL packet sent to client 0x25000030
Jun 17 08:15:48: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:idle request action
SWITCH(config-if)#
Jun 17 08:16:03: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting EAP_REQ for 0x25000030
Jun 17 08:16:03: dot1x_auth_bend Gi1/0/37: during state auth_bend_request, got event 7(eapReq)
Jun 17 08:16:03: @@@ dot1x_auth_bend Gi1/0/37: auth_bend_request -> auth_bend_request
Jun 17 08:16:03: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:request request action
Jun 17 08:16:03: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering request state
Jun 17 08:16:03: dot1x-ev:[Gi1/0/37] Sending EAPOL packet to group PAE address
Jun 17 08:16:03: dot1x-registry:registry:dot1x_ether_macaddr called
Jun 17 08:16:03: dot1x-ev:[Gi1/0/37] Sending out EAPOL packet
SWITCH(config-if)#
Jun 17 08:16:03: dot1x-packet:EAPOL pak Tx - Ver: 0x3 type: 0x0
Jun 17 08:16:03: dot1x-packet: length: 0x0005
Jun 17 08:16:03: dot1x-packet:EAP code: 0x1 id: 0x1 length: 0x0005
Jun 17 08:16:03: dot1x-packet: type: 0x1
Jun 17 08:16:03: dot1x-packet:[081f.f362.5862, Gi1/0/37] EAPOL packet sent to client 0x25000030
SWITCH(config-if)#
Jun 17 08:16:19: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting EAP_REQ for 0x25000030
Jun 17 08:16:19: dot1x_auth_bend Gi1/0/37: during state auth_bend_request, got event 7(eapReq)
Jun 17 08:16:19: @@@ dot1x_auth_bend Gi1/0/37: auth_bend_request -> auth_bend_request
Jun 17 08:16:19: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:request request action
Jun 17 08:16:19: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering request state
Jun 17 08:16:19: dot1x-ev:[Gi1/0/37] Sending EAPOL packet to group PAE address
Jun 17 08:16:19: dot1x-registry:registry:dot1x_ether_macaddr called
Jun 17 08:16:19: dot1x-ev:[Gi1/0/37] Sending out EAPOL packet
SWITCH(config-if)#
Jun 17 08:16:19: dot1x-packet:EAPOL pak Tx - Ver: 0x3 type: 0x0
Jun 17 08:16:19: dot1x-packet: length: 0x0005
Jun 17 08:16:19: dot1x-packet:EAP code: 0x1 id: 0x1 length: 0x0005
Jun 17 08:16:19: dot1x-packet: type: 0x1
Jun 17 08:16:19: dot1x-packet:[081f.f362.5862, Gi1/0/37] EAPOL packet sent to client 0x25000030
SWITCH(config-if)#
Jun 17 08:16:34: dot1x-ev:[081f.f362.5862, Gi1/0/37] Received an EAP Timeout
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting EAP_TIMEOUT for 0x25000030
Jun 17 08:16:34: dot1x_auth_bend Gi1/0/37: during state auth_bend_request, got event 12(eapTimeout)
Jun 17 08:16:34: @@@ dot1x_auth_bend Gi1/0/37: auth_bend_request -> auth_bend_timeout
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering timeout state
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:request timeout action
Jun 17 08:16:34: dot1x_auth_bend Gi1/0/37: idle during state auth_bend_timeout
Jun 17 08:16:34: @@@ dot1x_auth_bend Gi1/0/37: auth_bend_timeout -> auth_bend_idle
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering idle state
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] Posting AUTH_TIMEOUT on Client 0x25000030
Jun 17 08:16:34: dot1x_auth Gi1/0/37: during state auth_authenticating, got event 14(authTimeout)
Jun 17 08:16:34: @@@ dot1x_auth Gi1/0/37: auth_authenticating -> auth_authc_result
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:exiting authenticating state
Jun 17 08:16:34: dot1x-sm:[081f.f362.5862, Gi1/0/37] 0x25000030:entering authc result state
Jun 17 08:16:34: %DOT1X-5-FAIL: Authentication failed for client (081f.f362.5862) on Interface Gi1/0/37 AuditSessionID 0A91604200000F5E55EFF834
Jun 17 08:16:34: dot1x-packet:[081f.f362.5862, Gi1/0/37] Dot1x did not receive any key data
Jun 17 08:16:34: dot1x-ev:[081f.f362.5862, Gi1/0/37] Processing client delete for hdl 0x25000030 sent by Auth Mgr
Jun 17 08:16:34: dot1x-ev:[081f.f362.5862, Gi1/0/37] 081f.f362.5862: sending canned failure due to method termination
Jun 17 08:16:34: dot1x-ev:[Gi1/0/37] Sending EAPOL packet to group PAE address
Jun 17 08:16:34: dot1x-registry:registry:dot1x_ether_macaddr called
Jun 17 08:16:34: dot1x-ev:[Gi1/0/37] Sending out EAPOL packet
Jun 17 08:16:34: dot1x-packet:EAPOL pak Tx - Ver: 0x3 type: 0x0
Jun 17 08:16:34: dot1x-packet: length: 0x0004
SWITCH(config-if)#
Jun 17 08:16:34: dot1x-packet:EAP code: 0x4 id: 0x1 length: 0x0004
Jun 17 08:16:34: dot1x-packet:[081f.f362.5862, Gi1/0/37] EAPOL canned status packet sent to client 0x25000030
Jun 17 08:16:34: dot1x-ev:[081f.f362.5862, Gi1/0/37] Deleting client 0x25000030 (081f.f362.5862)
Jun 17 08:16:34: dot1x-ev:[081f.f362.5862, Gi1/0/37] Delete auth client (0x25000030) message
Jun 17 08:16:34: dot1x-ev:Auth client ctx destroyed

-----------------

I have no idea why this started happening suddenly. There has been no configuration changes, IOS updates, or phone firmware updates of late.

it seems like the switch is only starting the DOT1x process sometimes for phones. I have been trying to work this out for a few weeks. that said, this weekend passed our access switches were power cycled (power outage), DOT1x locked out half of our phones.

everything else works perfectly still, i.e. when the supplicant is a laptop/PC directly.

Has anyone seen this?. I know CDP bypass is not supported anymore ad ill need to move to MAB, but it is crazy that this just hit us like this.

[Arne Bier]

How annoying ... have you looked in your RADIUS server whether there are any attempts made to it when one of these phones fails to come up correctly? Or are you saying that the switch doesn't even attempt to make an 802.1X call to the RADIUS server?

If the RADIUS server is contacted every time then perhaps the next step in the investigation is to see why/where it's failing.

I don't think MAB is the answer if the switch is not even reaching out to the RADIUS server. Having said that, if there is a bug in the switch's code that handles the EAPOL frames then perhaps MAB is a workaround. Have you opened a TAC case?