Highlighted
Emerging Member
Posts: 75
Registered: ‎02-13-2012
Kudos: 25

4-way keying handshake timeout

I am seeing an issue with one of my CPE radios authenticating and was wondering if anyone has seen this issue or knew of a way to resolve this issue. In the AP I am seeing the following log message:

Sending deauth to MAC:ADDRESS:e0. Reason: 4-way keying handshake timeout (15).

The CPE log shows the same message except for replacing the "to" with a "from", then the CPE will try to authenticate again and will succeed. I am running 5.5.2 on both devices with WPA2-AES. The signal is quite strong with a -59 on the CPE side and -58 on the other, so I don't think thats the issue. This dance repeats itself once an hour, but I can stop it if I lock the CPE to the MAC Address of the AP. In case it matters the AP is a Titanium Rocket and the CPE is a NanoBridge. If anyone has any ideas or things to try I would appreciate it.

AP log of the issue (I know the time is off but its the same time):

14:30:12 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.1X: authenticated - EAP type: 21 (TTLS) (PMKSA cache)
14:30:15 hostapd: ath0: STA MAC:ADDRESS:e0 WPA: PTK: Failed to receive EAPOL-Key msg 4/4 response, all tries exhausted.
14:30:15 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.11: deauthenticated due to local deauth request
14:30:15 wireless: ath0 Sending deauth to MAC:ADDRESS:e0. Reason: 4-way keying handshake timeout (15).
14:30:15 wireless: ath0 STA-TRAFFIC-STAT mac=MAC:ADDRESS:e0 rx_packets=5311 rx_bytes=2277770 tx_packets=4751 tx_bytes=644689
14:30:15 wireless: ath0 Expired node:MAC:ADDRESS:e0
14:30:15 hostapd: ath0: STA MAC:ADDRESS:e0 RADIUS: stopped accounting session 509B3C57-0000000C
14:30:15 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.11: disassociated
14:30:20 wireless: ath0 MLME-AUTH.indication(addr=MAC:ADDRESS:e0)
14:30:20 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.11: associated
14:30:20 wireless: ath0 Registered node:MAC:ADDRESS:e0
14:30:23 hostapd: ath0: STA MAC:ADDRESS:e0 WPA: PTK: Failed to receive EAPOL-Key msg 4/4 response, all tries exhausted.
14:30:23 wireless: ath0 Sending deauth to MAC:ADDRESS:e0. Reason: 4-way keying handshake timeout (15).
14:30:23 wireless: ath0 STA-TRAFFIC-STAT mac=MAC:ADDRESS:e0 rx_packets=1 rx_bytes=153 tx_packets=5 tx_bytes=781
14:30:23 wireless: ath0 Expired node:MAC:ADDRESS:e0
14:30:23 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.11: deauthenticated due to local deauth request
14:30:23 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.11: disassociated
14:30:28 wireless: ath0 MLME-AUTH.indication(addr=MAC:ADDRESS:e0)
14:30:28 wireless: ath0 Registered node:MAC:ADDRESS:e0
14:30:28 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.11: associated
14:30:28 hostapd: ath0: STA MAC:ADDRESS:e0 WPA: pairwise key handshake completed (RSN)
14:30:28 hostapd: ath0: STA MAC:ADDRESS:e0 RADIUS: starting accounting session 509B3C57-0000000E
14:30:28 hostapd: ath0: STA MAC:ADDRESS:e0 IEEE 802.1X: authenticated - EAP type: 21 (TTLS) (PMKSA cache)


CPE log of the issue (I know the time is off but its the same time):


02:51:25 wpa-supplicant: CTRL-EVENT-EAP-STARTED EAP authentication started
02:51:25 wpa-supplicant: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected
02:51:34 wpa-supplicant: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
02:51:34 wpa-supplicant: WPA: Key negotiation completed with MAC:ADDRESS:b0
02:51:37 wireless: ath0 Received deauth from MAC:ADDRESS:b0. Reason: 4-way keying handshake timeout (15).
02:51:37 wireless: ath0 New Access Point/Cell address:Not-Associated
02:51:37 wpa-supplicant: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
02:51:42 wireless: ath0 Scan request completed
02:51:42 wpa-supplicant: Trying to associate with MAC:ADDRESS:b0 (SSID='mySSID' freq=5770 MHz)
02:51:42 wireless: ath0 Set Mode:Managed
02:51:42 wireless: ath0 Set Frequency:5.77 GHz (Channel 154)
02:51:42 wireless: ath0 New Access Point/Cell address:MAC:ADDRESS:b0
02:51:42 wpa-supplicant: Associated with MAC:ADDRESS:b0
02:51:42 wpa-supplicant: WPA: Key negotiation completed with MAC:ADDRESS:b0
02:51:42 wpa-supplicant: CTRL-EVENT-CONNECTED - Connection to MAC:ADDRESS:b0 completed (reauth)
02:51:42 wpa-supplicant: WPA: Key negotiation completed with MAC:ADDRESS:b0
02:51:43 wpa-supplicant: WPA: Key negotiation completed with MAC:ADDRESS:b0
02:51:44 wpa-supplicant: WPA: Key negotiation completed with MAC:ADDRESS:b0
02:51:45 wireless: ath0 Received deauth from MAC:ADDRESS:b0. Reason: 4-way keying handshake timeout (15).
02:51:45 wireless: ath0 New Access Point/Cell address:Not-Associated
02:51:45 wpa-supplicant: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
02:51:50 wireless: ath0 Scan request completed
02:51:50 wpa-supplicant: Trying to associate with MAC:ADDRESS:b0 (SSID='mySSID' freq=5770 MHz)
02:51:50 wireless: ath0 Set Mode:Managed
02:51:50 wireless: ath0 Set Frequency:5.77 GHz (Channel 154)
02:51:50 wireless: ath0 New Access Point/Cell address:MAC:ADDRESS:b0
02:51:50 wpa-supplicant: Associated with MAC:ADDRESS:b0
02:51:50 wpa-supplicant: WPA: Key negotiation completed with MAC:ADDRESS:b0
02:51:50 wpa-supplicant: CTRL-EVENT-CONNECTED - Connection to MAC:ADDRESS:b0 completed (reauth)
SuperUser
Posts: 21,761
Registered: ‎11-20-2011
Kudos: 7935
Solutions: 233

Re: 4-way keying handshake timeout

Yay, somebody who has replicated this.

Me and "twinkletoes" were talking about this in another thread. It's rare, but it shows up occasionally. Changing channels fixes the issue... somehow. (It doesn't make any sense, but give it a shot.)


isp builder | linux sorcerer | datacenter automation conjurer | blog: blog.engineered.online
link to our slack channel on the blog
Regular Member
Posts: 462
Registered: ‎10-01-2009
Kudos: 28
Solutions: 1

Re: 4-way keying handshake timeout

See this quite a bit. I still havent gotten any solid answer on a fix.
forum.ubnt.com/showthread.php?t=25140
To expand on this a bit, changing channels sometimes fixes it. Rebooting AP first then CPE sometimes fixes it but not always.
SuperUser
Posts: 21,761
Registered: ‎11-20-2011
Kudos: 7935
Solutions: 233

Re: 4-way keying handshake timeout

See this quite a bit. I still havent gotten any solid answer on a fix.

forum.ubnt.com/showthread.php?t=25140

To expand on this a bit, changing channels sometimes fixes it. Rebooting AP first then CPE sometimes fixes it but not always.


Alright, you might try upgrading this link to 5.5.4RC (apply for the beta forum) and see if it fixes the issue.

Something else you might try is disabling encryption on both radios (make sure to do the client/sta first, obviously), then re-enabling WPA2-AES.


isp builder | linux sorcerer | datacenter automation conjurer | blog: blog.engineered.online
link to our slack channel on the blog
SuperUser
Posts: 6,254
Registered: ‎08-26-2009
Kudos: 1899
Solutions: 63

Re: 4-way keying handshake timeout

Ironically I'm not seeing this symptom much with 5.5.2 or 5.5.4beta but with 5.5.4b2 and 5.5.4RC it seems more prevalent. In at least one case it is related to autoack distance being problematic for a customer very close to a sector and disabling autoack on their radio seems to make it go away. Changing frequency also makes it possible for their radio to fully associate. In another case it does not appear to be related to autoack. In both cases it is prevalent with 5.5.4-RC and not with 5.5.2.
Emerging Member
Posts: 75
Registered: ‎02-13-2012
Kudos: 25

Re: 4-way keying handshake timeout

Thanks for the quick responses. Its nice to see I'm not the only one experiencing this issue, but disheartening to know there isn't a firm resolution. I found that when I switch the CPE radio over to a new AP the problem goes away as well...which only further confuses the issue for me as this isn't the only CPE radio on this AP but it is the only one that has this issue. This connection is 4.7miles on a 20Mhz channel, should auto-ack be an issue at this distance?

As far as the suggestions I will try the following things (one at a time) during a maintenance window:
-Reboot the AP and then the CPE
-Turn off WPA encryption and then turn it back on
-Change channel on the sector

It would be nice if I could use airview to find another clean channel, but maybe that is another reason to upgrade to 5.5.4RC.
SuperUser
Posts: 21,761
Registered: ‎11-20-2011
Kudos: 7935
Solutions: 233

Re: 4-way keying handshake timeout

Ironically I'm not seeing this symptom much with 5.5.2 or 5.5.4beta but with 5.5.4b2 and 5.5.4RC it seems more prevalent. In at least one case it is related to autoack distance being problematic for a customer very close to a sector and disabling autoack on their radio seems to make it go away. Changing frequency also makes it possible for their radio to fully associate. In another case it does not appear to be related to autoack. In both cases it is prevalent with 5.5.4-RC and not with 5.5.2.


The only link I have problems with this is on a NSL5 link, but there are also REALLY crappy reflections... I'm wondering if it's the reflections causing it.

I hasn't happened in over 6 months though, it's pretty weird.


isp builder | linux sorcerer | datacenter automation conjurer | blog: blog.engineered.online
link to our slack channel on the blog
Regular Member
Posts: 462
Registered: ‎10-01-2009
Kudos: 28
Solutions: 1

Re: 4-way keying handshake timeout

Yeah definitely a mystery problem.

Only happens to us with NBM5's
We can replace the NB and put it at another customer on a different AP and never see the problem again.
Only pops up sporadically but when it does its a pain to get rid of. Sounds like my ex wife.
SuperUser
Posts: 6,254
Registered: ‎08-26-2009
Kudos: 1899
Solutions: 63

Re: 4-way keying handshake timeout

I hasn't happened in over 6 months though, it's pretty weird.


Well it seems the hostapd 2/4 and 4/4 failures are just some symptom of a bad link that isn't passing enough traffic for even the initial handshake to complete. And I have a few cases now where 5.5.2 works fine and 5.5.4-RC doesn't, and it can be easily repeated by loading back and forth between firmwares. Or so I thought. I got 6 test images between 5.5.4-beta and 5.5.4-RC and sometimes they all work, sometimes they work after 10 minutes, and it's different on different links, the only common thing is that it didn't seem to happen under 5.5.2. Not even sure if that's true anymore as now I'm having a harder time reliably reproducing the problem. It seems to be related to changes in airmax.
SuperUser
Posts: 21,761
Registered: ‎11-20-2011
Kudos: 7935
Solutions: 233

Re: 4-way keying handshake timeout

Well it seems the hostapd 2/4 and 4/4 failures are just some symptom of a bad link that isn't passing enough traffic for even the initial handshake to complete. And I have a few cases now where 5.5.2 works fine and 5.5.4-RC doesn't, and it can be easily repeated by loading back and forth between firmwares. Or so I thought. I got 6 test images between 5.5.4-beta and 5.5.4-RC and sometimes they all work, sometimes they work after 10 minutes, and it's different on different links, the only common thing is that it didn't seem to happen under 5.5.2. Not even sure if that's true anymore as now I'm having a harder time reliably reproducing the problem. It seems to be related to changes in airmax.


Explain my non airmax NSL5 link then Man Happy


isp builder | linux sorcerer | datacenter automation conjurer | blog: blog.engineered.online
link to our slack channel on the blog
Emerging Member
Posts: 75
Registered: ‎02-13-2012
Kudos: 25

Re: 4-way keying handshake timeout

Maybe it is a reflection issue, my chains have 12dB of difference. The vertical is great and the horizontal is pretty bad.
New Member
Posts: 32
Registered: ‎02-15-2009
Kudos: 3

Re: 4-way keying handshake timeout

I am seeing this log entry on one station I just upgraded from 5.5.2 to 5.5.4RC 2 days ago. I have 2 of the 20+ stations and the AP on 5.5.4RC and have adaptive rate on just one station. The station not using adaptive rate is having the issue. The one in issue is a Rocket M2. The other station is a nano bridge M2. I changed channels and re-entered the AES key on the station, rebooted the AP first, then the Station. The issue goes away for 1-2 hours after these changes and then returns. Usually.
I plan on returning the station to 5.5.2 tonight and check it in the morning.
-edit, I also, turned off auto ack same problem.
Member
Posts: 170
Registered: ‎10-04-2011
Kudos: 40
Solutions: 2

Re: 4-way keying handshake timeout

I had this issue on a unit a few days ago with cpe running 5.5, I upgraded the station and ap to 5.5.2 and all the problems went away. I noticed while this station was flaking out the application was kicking most or all of it connections. Around 27 radios were being kicked but I wouldn't loose connection to the ap just the stations. Don't know if this helps but I was pulling my hair out until I upgraded the firmware.
Sent from my SPH-L900 using Tapatalk 2
Emerging Member
Posts: 75
Registered: ‎02-13-2012
Kudos: 25

Re: 4-way keying handshake timeout

This morning I tried rebooting the AP and then the CPE device, this did not help the situation. I then tried turning off the WPA encryption and turning it back on, this so far has seemed to clear up the issue, it has been 2 hours without this issue happening. I will keep an eye on it, hopefully this is cleared up for good.

As far as the possibility of the reflection causing this issue, I have another CPE on this same sector (same setup) that is worse without this issue...but maybe this is part of the issue.
New Member
Posts: 32
Registered: ‎02-15-2009
Kudos: 3

Re: 4-way keying handshake timeout

Downgraded the firmware overnight back to 5.5.2. The airControl log and Station log are not showing the issues I was seeing, so far. Only being 5 hours later, I will continue to monitor it today.
Emerging Member
Posts: 75
Registered: ‎02-13-2012
Kudos: 25

Re: 4-way keying handshake timeout

My CPE connection is still running clean, turning off WPA and then re-enabling it resolved the issue.
Member
Posts: 165
Registered: ‎10-24-2012
Kudos: 21

Re: 4-way keying handshake timeout

Has anyone ever found a definitive cause of this problem? I have a 37 mile link that goes into spats of this problem for hours at a time.

Thanks.
Member
Posts: 165
Registered: ‎10-24-2012
Kudos: 21

Re: 4-way keying handshake timeout

Turning off encryption bring the link back up perfectly. WPA2 security causes the handshake problem I showed above.

SuperUser
Posts: 21,761
Registered: ‎11-20-2011
Kudos: 7935
Solutions: 233

Re: 4-way keying handshake timeout


@TurnipTruck wrote:

Turning off encryption bring the link back up perfectly. WPA2 security causes the handshake problem I showed above.


Oh, you mean like in post #4? Man Happy



isp builder | linux sorcerer | datacenter automation conjurer | blog: blog.engineered.online
link to our slack channel on the blog
New Member
Posts: 7
Registered: ‎02-14-2016
Kudos: 1

Re: 4-way keying handshake timeout

[ Edited ]

This issue still exists in 7.2 code.  I have a Rocket5AC with 3 PBE5AC 300's.  I set the R5AC to Access Point PTMP, set WPA to PSK-AES and used a 12 digit strong key(Upper, Lower, numbers and a bang).  I could ONLY get 1 radio to connect.  I had to take WPA back to NONE, have all 3 radios connect successfully, then turn back on WPA with PSK-AES.  This time I used an 8 digit strong key.  Same U,L,N,bang just shorter.  Everything works fine now.

 

Clearly their is a bug in the UBNT code.

 

I just wanted to say THANK YOU to this thread.  Finding this resolved the issue.  I would NEVER have thought the key length or related key was the issue as you only get 1 option for WPA and security... I paste the key ensuring no EXTRA charaters were in the key..   weird issue.