"WPA: EAPOL-Key timeout" for certain devices
-
All,
I've been a user both and home and work for years. This seems to have just started, maybe when I updated from 2.0.1 to 2.0.2. I just moved to the 2.1 beta but the issue persists. From reading online, it might be related to a power saving setting in the devices but I'm not sure. Disabling power saving in the wifi settings doesn't help.
Macbook Pro and Android handsets consistently get the EAPOL-Key timeout error in the logs. I have a Linux laptop and a Roku that have no problems at all. From wireless.log, filtered on the Android MAC:
Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: event 1 notification Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: start authentication Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key frame (2/4 Pairwise) Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 3/4 msg of 4-Way Handshake Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:19:11 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 3/4 msg of 4-Way Handshake Jan 27 16:19:12 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:19:12 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 3/4 msg of 4-Way Handshake Jan 27 16:19:13 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:19:13 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 3/4 msg of 4-Way Handshake Jan 27 16:19:14 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:19:14 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port Jan 27 16:19:14 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to local deauth request Jan 27 16:19:14 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deassociated Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: event 1 notification Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: start authentication Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key frame (2/4 Pairwise) Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 3/4 msg of 4-Way Handshake Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key frame (4/4 Pairwise) Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: authorizing port Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx RADIUS: starting accounting session 5105A7C6-00000004 Jan 27 16:19:16 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN) Jan 27 16:19:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:19:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:19:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:19:47 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:19:47 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:19:47 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key frame (2/2 Group) Jan 27 16:19:47 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN) Jan 27 16:20:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:20:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key frame (2/2 Group) Jan 27 16:20:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN) Jan 27 16:21:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:21:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:21:46 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:21:47 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:21:47 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:21:48 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:21:48 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 16:21:49 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 16:21:49 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port Jan 27 16:21:49 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to local deauth request Jan 27 16:21:49 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deassociated
I can see that it doesn't happen at the same point every time. Sometimes during the 4-Way, sometimes during the Group Key Handshake.
This shows up sometimes as well but doesn't seem as disruptive to the device working. As you can see, this time it timed out but didn't deassociate:
Jan 27 17:08:38 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 17:08:38 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout Jan 27 17:08:38 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/2 msg of Group Key Handshake Jan 27 17:08:38 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key frame (2/2 Group) Jan 27 17:08:38 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN) Jan 27 17:08:38 hostname hostapd: ath0_wlan0: STA xx:xx:xx:xx:xx:xx WPA: received EAPOL-Key 2/2 Group with unexpected replay counter
Tried setting a static channel but that didn't seem to affect very much.
WPA2/TKIP/AES anything else I can provide?Thanks and prost!
-
Same thing here! My logs are full of those messages.
-
I switched from AES to TKIP and the deassociations seem to have stopped. I'm still getting "EAPOL-Key timeout" occasionally but it rarely causes a lost connection. I'd still like to understand why of all my devices, only the Mac and Android don't play nicely with pfSense's implementation of AES. OR if there's something else happening.
-
For me it's all Android devices. I'll try TKIP.
-
hase, is your wifi interface bridged to any other interface?
-
Yes it is. To another physical interface. You think that's messing with the wireless crypto?
-
Mine is also bridged to my LAN.
-
I keep testing various other settings. The only thing that appears to work is disabling WPA. I've not tested with WEP.
Hardware:
ath0@pci0:0:12:0: class=0x020000 card=0x1012185f chip=0x0013168c rev=0x01 hdr=0x00
-
I keep seeing the same errors so I increased the re-key interval just to minimize the frequency.
However I noticed that every time there is a WPA re-keying, the first attempt gets the "EAPOL-Key timeout", but the second one succeeds:2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: WPA rekeying GTK
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: sending 1/2 msg of Group Key Handshake
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: EAPOL-Key timeout
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: sending 1/2 msg of Group Key Handshake
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: EAPOL-Key timeout
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: sending 1/2 msg of Group Key Handshake
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: EAPOL-Key timeout
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: sending 1/2 msg of Group Key Handshake
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: EAPOL-Key timeout
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy IEEE 802.1X: unauthorizing port
2013-01-30 9:14 AM,Info,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy IEEE 802.11: deauthenticated due to local deauth request
2013-01-30 9:14 AM,Info,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy IEEE 802.11: deassociated
2013-01-30 9:14 AM,Info,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy IEEE 802.11: associated
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: event 1 notification
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: start authentication
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy IEEE 802.1X: unauthorizing port
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: sending 1/4 msg of 4-Way Handshake
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: received EAPOL-Key frame (2/4 Pairwise)
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: sending 3/4 msg of 4-Way Handshake
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: received EAPOL-Key frame (4/4 Pairwise)
2013-01-30 9:14 AM,Debug,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy IEEE 802.1X: authorizing port
2013-01-30 9:14 AM,Info,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy RADIUS: starting accounting session 510907A5-00000014
2013-01-30 9:14 AM,Info,192.168.1.1,run0_wlan0: STA yy:yy:yy:yy:yy:yy WPA: pairwise key handshake completed (RSN)The other thing is the reference to 802.1X and RADIUS which I don't use and have never configured in the WLAN interface settings.
UPDATE:
An iPhone 4 is also behaving the same way, with EAPOL-Key timeout errors at the first re-key attempt -
I live in an apartment with dozens of competing wifi APs. When I moved the AP to another room, it appears to work better. I brought in and tested another AP and the 2.4ghz range was just as useless. The 5ghz worked perfectly. I've not done much more troubleshooting, but my current theory is too much competition on the frequency. If anyone has any recommendations or tests they'd like me to look at, I'll still be happy to help.
???
-
Download the WiFi Analyzer Android app to your phone, start it and switch to channel view. You might find a channel or channel range much less busy than the others.
There are WiFi chipsets supported by pfSense that can operate as APs in 5GHz and both 5GHz and 2.4GHz
-
I've been messing with that for days now. There are no open areas, switching to a less used channel helps temporarily but they're all fighting for limited space.
I've got a few things that can't support 5ghz so I "fixed it" with a wired AP in the other room. When I plugged in the second AP in the office with the pfSense box, it had the same problem. When I plug it into a drop in the same room as the Roku, 15-20 feet away, it works perfectly.
I don't do wireless professionally but am a network engineer. Constant retransmissions and timeouts on one frequency, plus a huge number of competing APs and who knows what else, but not another makes me pretty sure this is an interference issue.