Issue WPA2 Enterprise Client

Hello all,

I'm having an issue connecting my custom imx6 based router to a wpa2 enterprise network.

Firstly, the router hosting the enterprise network is just a Pi Zero with OpenWrt installed on it. It also locally hosts the radius server (lightly followed this guide) to set it up. I'm able to connect to it properly and get internet with my Windows laptop, so I know the basic setup works.

If I try to connect to it, I can see from wpa_cli (or just with logread) that I am successfully authorized by the radius server; however, immediately afterwards I see that it disconnects and the output is not particularly helpful.

wpa_supplicant conf file
network={
	scan_ssid=1
	ssid="MY-SSID"
	key_mgmt=WPA-EAP
	identity="bob"
	password="hello"
	phase2="auth=MSCHAPV2"
	eap=PEAP
	proto=RSN
	bssid=B8:27:EB:E3:59:EF
	beacon_int=100
}

output from wpa_supplicant
root@OpenWrt:~# wpa_supplicant -Dnl80211 -iwlan0 -c wpa.conf 
Successfully initialized wpa_supplicant
wlan0: Trying to associate with SSID 'MY-SSID'
wlan0: Associated with b8:27:eb:e3:59:ef
wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=admin@example.org/CN=Example Certificate Authority' hash=82c21f74943cd8b4eeac0e382b8f9e950a880d91e4866fd641690d8bab865d6f
wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=FR/ST=Radius/O=Example Inc./CN=Example Server Certificate/emailAddress=admin@example.org' hash=3318097686820d6fbf39837e39d3c7e50d326d5fc5e4798ca4e9529fd8cfa633
EAP-MSCHAPV2: Authentication succeeded
EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:e3:59:ef completed [id=0 id_str=]
wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:e3:59:ef reason=0 locally_generated=1
wlan0: Trying to associate with SSID 'MY-SSID'

As you can see, it just gives reason=0, which I have not been able to find good info on what to do with that.

Here's my wireless config for the client. Note that I've added some variables for my own use, which, as far as I know, is safe to do.
I will also note that I usually also use the travelmate package, but I've tried all this with it both off and on.

client-side /etc/config/wireless
config wifi-iface 'net_name'
	option device 'radio0'
	option network 'wan'
	option mode 'sta'
	option ssid 'MY-SSID'
	option channel '11'
	option encryption 'wpa2+ccmp'
	option disabled '1'
	option is_hidden '0'
	option bssid 'B8:27:EB:E3:59:EF'
	option eap_type 'peap'
	option identity 'bob'
	option password 'hello'
	option name 'net_name'

Here is the config for the host network. It gets internet in from an ethernet cable. Again, I was able to connect and get internet successfully if connecting from my Windows laptop, so I doubt the problem is on this side.

host-side /etc/config/wireless
config wifi-iface 'default_radio0'
        option device 'radio0'
        option network 'lan'
        option mode 'ap'
        option ssid 'MY-SSID'
        option wmm '0'
        option disassoc_low_ack '0'
        option auth_secret 'testing123'
        option auth_server '127.0.0.1'
        option acct_server '127.0.0.1'
        option encryption 'wpa2'
        option acct_port '1813'
        option auth_port '1812'

Remarks that may or may not be useful:

  • If using wpad (built-in full) or wpa-supplicant (built-in full) on the client, it would try to force using tls 1.0, which is rejected by default freeradius3 settings.

    • using wpad-openssl or wpa-supplicant-openssl (both of which are under the 'mini' version of their program) allowed it to use tls 1.2
  • I also failed to connect with an Ubuntu laptop; however that appeared to fail due to an auth issue and I have not spent much time trying to troubleshoot it.

As a final disclaimer: While I'm no longer new at this, I'm still no expert, so hopefully this is just some silly problem.

Thanks for any help or insight you can give!

Have you tried to debug from the radius side by running freeradius -X on your pi in a console ? No Mac address or dhcp problems?

I have had several instabilities with peap mschapv2, particularly on windows 10 clients ( which has nothing to do with openwrt, at that time I still used tomato on the APs).
On Android it worked quite stable.

Since I made the step to use eap/tls (client certificates), the client setup is much easier, just need to bring the client certificate and the ca certificate to the client once for installation. Also I no longer have authentication issues as before, and authentication is much faster, and it is more future proof, as wpa3 enterprise only supports eap/tls, if I am remember it correctly.

Can you post both log files, client and host for the same time frame ? This could also be a mac address filter or dhcp problem.

Don't run wpa_supplicant directly, use the UCI system. Travelmate works by disabling all the STA interfaces except the one in use, so running without Travelmate you need to remove the option disabled line.

I have tried running radius with the debugging flag and nothing caught my eye.

My priority right now was making sure my router would work with any sort of network. So testing that certs and all that worked properly would be my next step. Although I would think that if it passes the auth in the first place, that means that the radius side is working correctly.

Here are the logs from each thing for two cycles of auth, connect, disconnect. Note that I leave out dmesg output because it is only two lines (first saying wifi link is not ready, next saying it becomes ready)

The output from radiusd -X alone is longer than is allowed in a forum post. Is there a good way I could share it through the forum, or would my best bet be to put it on a google drive or something?

Output from wpa_supplicant
Successfully initialized wpa_supplicant
wlan0: Trying to associate with SSID 'MY-SSID'
wlan0: Associated with b8:27:eb:e3:59:ef
wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=admin@example.org/CN=Example Certificate Authority' hash=82c21f74943cd8b4eeac0e382b8f9e950a880d91e4866fd641690d8bab865d6f
wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=FR/ST=Radius/O=Example Inc./CN=Example Server Certificate/emailAddress=admin@example.org' hash=3318097686820d6fbf39837e39d3c7e50d326d5fc5e4798ca4e9529fd8cfa633
EAP-MSCHAPV2: Authentication succeeded
EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:e3:59:ef completed [id=0 id_str=]
wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:e3:59:ef reason=0 locally_generated=1
wlan0: Trying to associate with SSID 'MY-SSID'
wlan0: Associated with b8:27:eb:e3:59:ef
wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=admin@example.org/CN=Example Certificate Authority' hash=82c21f74943cd8b4eeac0e382b8f9e950a880d91e4866fd641690d8bab865d6f
wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=FR/ST=Radius/O=Example Inc./CN=Example Server Certificate/emailAddress=admin@example.org' hash=3318097686820d6fbf39837e39d3c7e50d326d5fc5e4798ca4e9529fd8cfa633
EAP-MSCHAPV2: Authentication succeeded
EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:e3:59:ef completed [id=0 id_str=]
wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:e3:59:ef reason=0 locally_generated=1
wlan0: Trying to associate with SSID 'MY-SSID'
wlan0: Associated with b8:27:eb:e3:59:ef
wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
Output from following logread before running wpa_supplicant
Sat Feb  6 21:35:11 2021 kern.info kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sat Feb  6 21:35:15 2021 daemon.info [2052]: wlan0: carrier acquired
Sat Feb  6 21:35:15 2021 kern.info kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Sat Feb  6 21:35:15 2021 daemon.info [2052]: wlan0: IAID ca:2b:d4:fd
Sat Feb  6 21:35:15 2021 daemon.info [2052]: wlan0: adding address fe80::76e9:bcfb:45eb:8fd9
Sat Feb  6 21:35:16 2021 daemon.info [2052]: wlan0: soliciting a DHCP lease
Sat Feb  6 21:35:16 2021 daemon.info [2052]: wlan0: soliciting an IPv6 router
Sat Feb  6 21:35:16 2021 daemon.info [2052]: wlan0: carrier lost
Sat Feb  6 21:35:16 2021 daemon.info [2052]: wlan0: deleting address fe80::76e9:bcfb:45eb:8fd9
Sat Feb  6 21:35:24 2021 daemon.info [2052]: wlan0: carrier acquired
Sat Feb  6 21:35:24 2021 daemon.info [2052]: wlan0: IAID ca:2b:d4:fd
Sat Feb  6 21:35:24 2021 daemon.info [2052]: wlan0: adding address fe80::76e9:bcfb:45eb:8fd9
Sat Feb  6 21:35:24 2021 daemon.info [2052]: wlan0: soliciting a DHCP lease
Sat Feb  6 21:35:24 2021 daemon.info [2052]: wlan0: soliciting an IPv6 router
Sat Feb  6 21:35:25 2021 daemon.info [2052]: wlan0: carrier lost
Sat Feb  6 21:35:25 2021 daemon.info [2052]: wlan0: deleting address fe80::76e9:bcfb:45eb:8fd9
Sat Feb  6 21:35:28 2021 daemon.info [2052]: wlan0: carrier acquired
Sat Feb  6 21:35:28 2021 daemon.info [2052]: wlan0: IAID ca:2b:d4:fd
Sat Feb  6 21:35:28 2021 daemon.info [2052]: wlan0: adding address fe80::76e9:bcfb:45eb:8fd9
Sat Feb  6 21:35:29 2021 daemon.info [2052]: wlan0: carrier lost
Sat Feb  6 21:35:29 2021 daemon.info [2052]: wlan0: deleting address fe80::76e9:bcfb:45eb:8fd9

I'm aware with how it works with UCI and travelmate. If I just set disabled=0 and try to connect the normal way, I have the same issue.

I was just manually doing it with wpa_supplicant so I could easily start and stop for testing. (normally it would just keep trying to connect forever, or with travelmate until it reaches a certain count).

I did also verify that connecting to a wpa-psk network through wpa_supplicant worked as expected.

Sorry, your host log side looks strange. In my log the host side looks like:

Mon Feb  8 07:13:49 2021 daemon.info hostapd: wlan1: STA 11:82:c5:2f:db:8f IEEE 802.11: authenticated
Mon Feb  8 07:13:49 2021 daemon.info hostapd: wlan1: STA 11:82:c5:2f:db:8f IEEE 802.11: associated (aid 1)
Mon Feb  8 07:13:49 2021 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED 11:82:c5:2f:db:8f
Mon Feb  8 07:13:49 2021 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Mon Feb  8 07:13:49 2021 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-SUCCESS2 11:82:c5:2f:db:8f
Mon Feb  8 07:13:49 2021 daemon.info hostapd: wlan1: STA 11:82:c5:2f:db:8f WPA: pairwise key handshake completed (RSN)
Mon Feb  8 07:13:49 2021 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 11:82:c5:2f:db:8f
Mon Feb  8 07:13:49 2021 daemon.info hostapd: wlan1: STA 11:82:c5:2f:db:8f RADIUS: starting accounting session F8EDF826B3E4CFDF
Mon Feb  8 07:13:49 2021 daemon.info hostapd: wlan1: STA 11:82:c5:2f:db:8f IEEE 802.1X: authenticated - EAP type: 13 (TLS)

maybe you have to switch on some hostapd logging ?

see https://openwrt.org/docs/guide-developer/debugging

1 Like

Toward the end of the RADIUS server interaction it should say that it sent an approved response to the AP.

In the AP config you have wmm = 0 it really should be 1. WMM is required for n or ac operation.

Oh, I apologize for being unclear. Both of those outputs were from the client router.

Here's the logread output from host during connection attempt
Mon Feb  8 21:47:29 2021 daemon.info hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.11: associated
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: event 1 notification
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: start authentication
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: start authentication
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: unauthorizing port
Mon Feb  8 21:47:29 2021 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 00:25:ca:2b:d4:fd
Mon Feb  8 21:47:29 2021 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 172)
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=172 len=8) from STA: EAP Response-Identity (1)
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: STA identity 'bob'
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: RADIUS Received 80 bytes from RADIUS server
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.26 sec
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=173 len=22) from RADIUS server: EAP-Request-MD5 (4)
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 173)
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=173 len=6) from STA: EAP Response-unknown (3)
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:29 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: RADIUS Received 76 bytes from RADIUS server
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.40 sec
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=174 len=6) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 174)
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=174 len=200) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:30 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:31 2021 daemon.debug hostapd: wlan0: RADIUS Received 1068 bytes from RADIUS server
Mon Feb  8 21:47:31 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:31 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.62 sec
Mon Feb  8 21:47:31 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=175 len=1004) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:31 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 175)
Mon Feb  8 21:47:33 2021 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-RETRANSMIT2 00:25:ca:2b:d4:fd
Mon Feb  8 21:47:33 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 175)
Mon Feb  8 21:47:33 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=175 len=6) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:33 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:33 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Received 1064 bytes from RADIUS server
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.44 sec
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=176 len=1000) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 176)
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=176 len=6) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Received 783 bytes from RADIUS server
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.45 sec
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=177 len=721) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 177)
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=177 len=128) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:34 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Received 107 bytes from RADIUS server
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.58 sec
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=178 len=49) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 178)
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=178 len=6) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Received 90 bytes from RADIUS server
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.43 sec
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=179 len=32) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 179)
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=179 len=31) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:35 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: RADIUS Received 124 bytes from RADIUS server
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.81 sec
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=180 len=66) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 180)
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=180 len=85) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:36 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:37 2021 daemon.debug hostapd: wlan0: RADIUS Received 132 bytes from RADIUS server
Mon Feb  8 21:47:37 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:37 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 1.03 sec
Mon Feb  8 21:47:37 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=181 len=74) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:37 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 181)
Mon Feb  8 21:47:39 2021 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-RETRANSMIT2 00:25:ca:2b:d4:fd
Mon Feb  8 21:47:39 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 181)
Mon Feb  8 21:47:39 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=181 len=29) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:39 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:39 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: RADIUS Received 96 bytes from RADIUS server
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.98 sec
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=1 id=182 len=38) from RADIUS server: EAP-Request-PEAP (25)
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 182)
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: received EAP packet (code=2 id=182 len=38) from STA: EAP Response-PEAP (25)
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: RADIUS Sending RADIUS message to authentication server
Mon Feb  8 21:47:40 2021 daemon.debug hostapd: wlan0: RADIUS Next RADIUS client retransmit in 3 seconds
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: RADIUS Received 165 bytes from RADIUS server
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: RADIUS Received RADIUS message
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.52 sec
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.11: binding station to interface 'wlan0'
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: old identity 'bob' updated with User-Name from Access-Accept 'bob'
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: decapsulated EAP packet (code=3 id=182 len=4) from RADIUS server: EAP Success
Mon Feb  8 21:47:41 2021 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-SUCCESS2 00:25:ca:2b:d4:fd
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: Sending EAP Packet (identifier 182)
Mon Feb  8 21:47:41 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: sending 1/4 msg of 4-Way Handshake
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: EAPOL-Key timeout
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: sending 1/4 msg of 4-Way Handshake
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: received EAPOL-Key frame (2/4 Pairwise)
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: sending 3/4 msg of 4-Way Handshake
Mon Feb  8 21:47:42 2021 daemon.info hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.11: disassociated
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: event 2 notification
Mon Feb  8 21:47:42 2021 daemon.info hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.11: disassociated
Mon Feb  8 21:47:42 2021 daemon.info hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.11: associated
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd WPA: event 1 notification
Mon Feb  8 21:47:42 2021 daemon.debug hostapd: wlan0: STA 00:25:ca:2b:d4:fd IEEE 802.1X: start authentication

I notice EAPOL-key timeout. I had not seen that before. I wonder if that is a cause?

I also rebuilt and put a newer build of OpenWrt on the pi zero since I realized the one that it had was old. So if there are any discrepancies from this point on, that could be the cause. (didn't fix anything though :frowning: )

The RADIUS authentication was successful (EAP-SUCCESS2). This then proceeds to the 4-way handshake which is used to exchange an AES session key for data transport. The timeout was because the first transmission of the first message was lost and had to be repeated. The client received the message on the second try and continued to message 2. That is harmless.

It appears that after completing the handshake, the client chose to disassociate.

Again, turn WMM on-- remove the option wmm 0.

So turn on wmm. When you google your disconnect, there can be several reason, for example :
https://www.raspberrypi.org/forums/viewtopic.php?t=251640

To me it looks like dhcp is set wrongly or something like that, or you somehow run into a client timeout.

oh yes, i tried your suggestion just before I left yesterday and sadly it did not help. I did both set it to 1 and removed the option entirely and there has been no change.

Thank you for explaining the process a bit more though!

I've tried turning on wmm, and the issue was not fixed.

If the problem had to do with dhcp, shouldn't that show up in the client or host's syslog or something?

I also am able to connect properly if I change the host to use another encryption (tried psk2 as well as open). So wouldn't that also verify that the dhcp works correctly.

at this point do you think combing through the packets with tcpdump would be useful?

thanks for all your help so far!

@Stefan1 or wait, maybe it is dhcp and it does appear in the the syslog!

I can see that the one of the last things it does before disconnect is always soliciting a lease.

...
Tue Feb  9 14:27:26 2021 daemon.notice netifd: Interface 'wan' is enabled
Tue Feb  9 14:27:26 2021 daemon.notice wpa_supplicant[9898]: wlan0: Trying to associate with SSID 'enterprise_net'
Tue Feb  9 14:27:27 2021 daemon.notice netifd: Network device 'wlan0' link is up
Tue Feb  9 14:27:27 2021 daemon.notice netifd: Interface 'wan' has link connectivity
Tue Feb  9 14:27:27 2021 daemon.notice netifd: Interface 'wan' is setting up now
Tue Feb  9 14:27:27 2021 daemon.notice wpa_supplicant[9898]: wlan0: Associated with b8:27:eb:e3:59:ef
Tue Feb  9 14:27:27 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
Tue Feb  9 14:27:27 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Tue Feb  9 14:27:27 2021 daemon.notice netifd: wan (13998): udhcpc: started, v1.30.1
Tue Feb  9 14:27:27 2021 daemon.notice netifd: wan (13998): udhcpc: sending discover
Tue Feb  9 14:27:27 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
Tue Feb  9 14:27:28 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Tue Feb  9 14:27:28 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Tue Feb  9 14:27:29 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=admin@example.org/CN=Example Certificate Authority' hash=6d66b82321ad1b677f0c5b317f5896ea121e17bed661d05d6786eca77a526502
Tue Feb  9 14:27:29 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=FR/ST=Radius/O=Example Inc./CN=Example Server Certificate/emailAddress=admin@example.org' hash=74729bce6a0d7153faad437830134739e3a1665a2ebb24d5de23de83e1809c97
Tue Feb  9 14:27:30 2021 daemon.notice netifd: wan (13998): udhcpc: sending discover
Tue Feb  9 14:27:32 2021 daemon.notice wpa_supplicant[9898]: EAP-MSCHAPV2: Authentication succeeded
Tue Feb  9 14:27:33 2021 daemon.notice wpa_supplicant[9898]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
Tue Feb  9 14:27:33 2021 daemon.notice netifd: wan (13998): udhcpc: sending discover
Tue Feb  9 14:27:34 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Tue Feb  9 14:27:34 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:e3:59:ef completed [id=0 id_str=]
Tue Feb  9 14:27:34 2021 daemon.info [1929]: wlan0: carrier acquired
Tue Feb  9 14:27:34 2021 daemon.info [1929]: wlan0: IAID ca:2b:d4:fd
Tue Feb  9 14:27:34 2021 daemon.info [1929]: wlan0: adding address fe80::b769:647:bf34:7891
Tue Feb  9 14:27:34 2021 daemon.info [1929]: wlan0: soliciting a DHCP lease
Tue Feb  9 14:27:34 2021 daemon.info [1929]: wlan0: soliciting an IPv6 router
Tue Feb  9 14:27:35 2021 daemon.notice wpa_supplicant[9898]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:e3:59:ef reason=0 locally_generated=1
Tue Feb  9 14:27:35 2021 daemon.info [1929]: wlan0: carrier lost
Tue Feb  9 14:27:35 2021 daemon.notice netifd: Network device 'wlan0' link is down
Tue Feb  9 14:27:35 2021 daemon.notice netifd: Interface 'wan' has link connectivity loss
Tue Feb  9 14:27:35 2021 daemon.info [1929]: wlan0: deleting address fe80::b769:647:bf34:7891
Tue Feb  9 14:27:35 2021 daemon.notice netifd: wan (13998): udhcpc: received SIGTERM
Tue Feb  9 14:27:35 2021 daemon.notice netifd: Interface 'wan' is now down
Tue Feb  9 14:27:35 2021 daemon.notice netifd: Interface 'wan' is disabled
Tue Feb  9 14:27:35 2021 daemon.notice netifd: Interface 'wan' is enabled
...

I guess the question remains though if udhcp is terminated because the disconnection, or if it disconnects because udhcp fails.

Clearly wpa supplicant disconnects. This doesn't have anything to do with DHCP afaik. For example IPv6 only LAN wouldn't work. It just disconnects. Check it's settings to see if there are some timeouts or something.

The reason Code 0 is bit strange, it is no failing code according to

If other authentication types work, I am running out of ideas. My feeling is that authentication takes too long, but there are authentication timeouts and obviously they do not show up in the reason.

If you are able to increase the log level for wpa_supplicant and the host, maybe you get an additional information...

which settings would I be looking into?

From /etc/config/wireless I can change things like disassoc_low_ack or ieee80211w_max_timeout, but I don't think those are really the settings that are problematic.

yeah, i've tried manually running both wpa_supplicant and hostapd with the -dd flags, and I still am not getting any more information about the disconnect. (Curiously, wpa_cli has more output than calling wpa_supplicant with the -dd flag, while hostapd_cli has less output than calling hostapd with the -dd flag. Both cli said the logging level was INFO)

One idea comes to my mind. I had problems with 802.11w, 802.11r and wpa2/enterprise. Switch off 802.11w testwise at the host. The problem only was with wpa2/eap, not with wpa2/psk...

I'm sorry, I'm not certain what you mean.

Do you mean explicitly set it to disabled in the wifi config of the host AP?

option ieee80211w '0'

Oh, it was not switched on in the wireless config. As the default is 0, this will not have any effect. Ok, let's face it, the fight is lost. Interesting would be whether eap/tls with a much shorter authentication would work. Have you tried not to set the accounting server ?