AP "could not extract EAP-Message from RADIUS message"

[-Hellsing-]

Hello,

There is a vWLC, several APs 1815i are connected to it, all APs are connected to one switch, the RADIUS server "FlexConnect Groups" is specified. All APs successfully work using the RADIUS server, but sometimes all fall off from the RADIUS server. The RADIUS server itself is available and pings from the AP, errors are visible in the point logs:

Aug 3 08:18:04 hostapd: apr1v1:802.1X: STA d8:c0:a6:be:7c:6b could not extract EAP-Message from RADIUS message
Aug 3 08:18:04 hostapd: apr1v1:802.1X: STA d8:c0:a6:be:7c:6b Supplicant used different EAP type: 1 (Identity)
Aug 3 08:18:04 kernel: [*08/03/2021 08:18:04.6799] hostapd:apr1v1:802.1X: STA d8:c0:a6:be:7c:6b could not extract EAP-Message from RADIUS message
Aug 3 09:09:11 kernel: [*08/03/2021 09:09:11.6199] chatter: client_ip_table :: ClientIPTable: traffic on wrong port (18) associated on (2) 6.192.204.96 2A:92:EA:A7:FE:5D
Aug 3 11:11:26 hostapd: apr0v1:802.11: STA e4:42:a6:e1:86:3d disassociated due to inactivity
Aug 3 13:23:13 kernel: [*08/03/2021 13:23:13.8299] chatter: client_ip_table :: ClientIPTable: traffic on wrong port (19) associated on (3) 6.192.204.96 98:AF:65:39:30:87
Aug 3 15:46:47 kernel: [*08/03/2021 15:46:47.6999] chatter: client_ip_table :: ClientIPTable: traffic on wrong port (18) associated on (2) 6.192.204.96 00:B3:62:22:C0:C7
Aug 3 15:51:55 hostapd: apr1v1:802.11: STA 98:af:65:39:30:87 disassociated due to inactivity

Debug ap client:

*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 dot1x - moving mobile 04:d3:b0:f0:59:10 into Authenticating state
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Entering Backend Auth Response state for mobile 04:d3:b0:f0:59:10
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Processing AAA Error 'No Server' (-7) for mobile 04:d3:b0:f0:59:10
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Deleting the PMK cache when de-authenticating the client.
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Global PMK Cache deletion failed.
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Succesfully freed AID 2, slot 1 on AP 78:0c:f0:65:b7:c0, #client on this slot 2
*Dot1x_NW_MsgTask_0: Aug 09 14:10:01.718: 04:d3:b0:f0:59:10 Sent Deauthenticate to mobile on BSSID 78:0c:f0:65:b7:ce slot 1(caller 1x_auth_pae.c:1894)

But if I reboot the AP, then everything will work successfully. What could be the reason that this error appears without periodic reboots?

[patoberli]

Sounds like a software bug. Which release is running on the APs?

[-Hellsing-]

8.5.171.0

[patoberli]

Ok that is current. There is a newer release, but it seems to fix other issues:

https://www.cisco.com/c/en/us/td/docs/wireless/controller/release/notes/crn85mr7_ircm.html#resolved-caveats

To your problem, you only have 1 radius server, this could also cause some special issues. Have a read into this document: https://www.cisco.com/c/en/us/support/docs/wireless-mobility/wireless-lan-wlan/118703-technote-wlc-00.html

This is a bit older but in most cases still completely valid. 

I can also see this error:

STA d8:c0:a6:be:7c:6b Supplicant used different EAP type: 1 (Identity)

This could also be a miss configuration on the client, which then could cause the radius server to stop authenticating clients temporarily.

[Rich R]

I have a TAC case open for a similar issue at the moment, same release.  Seems that the SSID loses the radius authentication config after any network disruption to the AP which causes it to rejoin the WLC.  Having a second radius server makes no difference, it's all lost.

On the AP can you use this command when you see the problem:"show authentication interface apr0v2 config"?

where r0 is the 2.4G radio and r1 is the 5G radio and v2 is WLAN 2 (they are numbered 0, 1, 2 ...) so the above example is for the 3rd WLAN on radio 0.

Normally the response should look like this:

AP#show authentication interface apr0v2 config
bssid=aa:bb:cc:dd:ee:ff
ssid=XXXXXXXXXX
auth=LOCAL
AP_OPER_MODE=CONNECTED
AP_OPER_MODE from WPA=CONNECTED
key_mgmt=WPA-EAP
AUTH_SERVER[0]=1.2.3.4
AUTH_SERVER_PORT[0]=1812
AUTH_SERVER[1]=5.6.7.8
AUTH_SERVER_PORT[1]=1812
group_cipher=CCMP
rsn_pairwise_cipher=CCMP

When it's broken you get this:

AP#show authentication interface apr0v2 config
% Authentication process for interface apr0v2 not started.

CAPWAP restart does not fix the problem.  Reloading the AP (mostly) does fix the problem.  TAC are 'researching' it at the moment ...

I'd suggest you also open a TAC case and happy to exchange SR numbers via DM if you want to get the TAC engineers to collaborate.

I'll post when I have any updates on the case.

[Rich R · Accepted solution]

TAC have confirmed my problem is caused by https://bst.cloudapps.cisco.com/bugsearch/bug/CSCvy00740 which is not fixed in 8.5 code but is fixed in 8.10 code so I'll be moving the affected site onto one of our 8.10 WLC pairs:

Bug details FYI

Symptom: When flexconnect AP connects and disconnects from the WLC 802.1x local auth SSIDs no longer work.
Conditions: Flexconnect AP with local auth 802.1x
AP goes to stand-alone mode and back into connected mode
Version: 8.5.171.0 and 8.5.161.9

Workaround: Reboot the AP
Use central 802.1x authentication