Deauthenticated Reason: 15=4WAY_HANDSHAKE_TIMEOUT on Wireless AC as 802.1x-client
Username: Bima
Origin: https://bugs.openwrt.org/index.php?do=details&task_id=1138
Supply the following if possible:
- Device problem occurs on
TP-Link Archer C7 (AC1750 version 2.0)
- Software versions of LEDE release, packages, etc.
LEDE Reboot 17.01.4 r3560-79f57e42 (newest release)
- Steps to reproduce
-
Set 802.11g radio as AP
-
Set 802.11a© radio as client for EDUROAM network with WPA2-EAP TTLS or PEAP (cipher CCMP) 802.11ac-80Mhz, fix channel (36), transmit power auto and country code DE (Germany)
3.1) Wait for 8:24 hours (or until the Maximum lifetime for PMKSA 70% of 43200 seconds reached and re-authentication is triggered)
OR
3.2) install wpa-cli, ping to any host to test internet and invoke "reauthenticate" in wpa-cli (in this way, after one or many times "reauthentication" is invoked, the internet will be unusable until "reauthenticate" is invoked again)
Description:
This Problem exist since long time ago either with openwrt or lede on 802.11ac radio. If 8 hours 24 minutes duration of router operation lasted (according to default dot11RSNAConfigPMKLifetime=43200 and dot11RSNAConfigPMKReauthThreshold=70 in wpa_supplicant) and the router try to "refresh" its pmksa by reauthenticate again with radius server, it will be disconnected with reason 15 (four way handshake timeout). For some reasons I need to keep my router always connected without "regular unwillingly" disconnections (except if there are software update in EDUROAM AP side). This is the kernel messages:
[ 25.195427] wlan0: authenticate with 11:22:33:44:55:66
[ 25.208453] wlan0: send auth to 11:22:33:44:55:66 (try 1/3)
[ 25.216280] wlan0: authenticated
[ 25.223602] wlan0: associate with 11:22:33:44:55:66 (try 1/3)
[ 25.343420] wlan0: associate with 11:22:33:44:55:66 (try 2/3)
[ 25.453654] wlan0: associate with 11:22:33:44:55:66 (try 3/3)
[ 25.563478] br-lan: port 2(wlan1) entered forwarding state
[ 25.569734] wlan0: association with 11:22:33:44:55:66 timed out
[ 25.879895] wlan0: authenticate with 11:22:33:44:55:66
[ 25.889865] wlan0: send auth to 11:22:33:44:55:66 (try 1/3)
[ 25.896496] wlan0: authenticated
[ 25.903550] wlan0: associate with 11:22:33:44:55:66 (try 1/3)
[ 25.911434] wlan0: RX AssocResp from 11:22:33:44:55:66 (capab=0x111 status=0 aid=1)
[ 25.920916] wlan0: associated
[ 25.924091] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 25.939403] wlan0: Limiting TX power to 17 dBm as advertised by 11:22:33:44:55:66
[ 47.737647] random: nonblocking pool is initialized
[30269.937723] wlan0: deauthenticated from 11:22:33:44:55:66 (Reason: 15=4WAY_HANDSHAKE_TIMEOUT)
[30271.332362] wlan0: authenticate with 11:22:33:44:55:66
[30271.342470] wlan0: send auth to 11:22:33:44:55:66 (try 1/3)
[30271.349075] wlan0: authenticated
[30271.355311] wlan0: associate with 11:22:33:44:55:66 (try 1/3)
[30271.363261] wlan0: RX AssocResp from 11:22:33:44:55:66 (capab=0x111 status=0 aid=3)
[30271.372768] wlan0: associated
[30271.441928] wlan0: Limiting TX power to 17 dBm as advertised by 11:22:33:44:55:66
Timestamps 25-47 are the initial boot of router and at 30269 the problem occurred. I can test this in quick way by installing wpa-cli and invoke reauthenticate command. The internet will be unusable even if the router still connected to AP. But by testing this way, I don't get "four way handshake timeout report message, except if I let the internet unusable for 15-30 minutes and the router is deauthenticated and reconnection occur automatically.
This are the system logs (the very first and the very last entries are before and after the problem occured):
Wed Nov 1 20:07:42 2017 daemon.info hostapd: wlan1: STA 11:11:11:11:11:11 WPA: group key handshake completed (RSN)
Wed Nov 1 20:11:48 2017 daemon.notice netifd: Network device 'wlan0' link is down
Wed Nov 1 20:11:48 2017 daemon.notice netifd: Interface 'wwan' has link connectivity loss
Wed Nov 1 20:11:48 2017 kern.info kernel: [30269.937723] wlan0: deauthenticated from 11:22:33:44:55:66 (Reason: 15=4WAY_HANDSHAKE_TIMEOUT)
Wed Nov 1 20:11:48 2017 daemon.notice netifd: wwan (1290): udhcpc: received SIGTERM
Wed Nov 1 20:11:49 2017 daemon.info odhcpd[824]: Using a RA lifetime of 0 seconds on br-lan
Wed Nov 1 20:11:50 2017 kern.info kernel: [30271.332362] wlan0: authenticate with 11:22:33:44:55:66
Wed Nov 1 20:11:50 2017 kern.info kernel: [30271.342470] wlan0: send auth to 11:22:33:44:55:66 (try 1/3)
Wed Nov 1 20:11:50 2017 kern.info kernel: [30271.349075] wlan0: authenticated
Wed Nov 1 20:11:50 2017 kern.info kernel: [30271.355311] wlan0: associate with 11:22:33:44:55:66 (try 1/3)
Wed Nov 1 20:11:50 2017 kern.info kernel: [30271.363261] wlan0: RX AssocResp from 11:22:33:44:55:66 (capab=0x111 status=0 aid=3)
Wed Nov 1 20:11:50 2017 kern.info kernel: [30271.372768] wlan0: associated
Wed Nov 1 20:11:50 2017 daemon.notice netifd: Network device 'wlan0' link is up
Wed Nov 1 20:11:50 2017 daemon.notice netifd: Interface 'wwan' has link connectivity
Wed Nov 1 20:11:50 2017 daemon.notice netifd: Interface 'wwan' is setting up now
Wed Nov 1 20:11:50 2017 kern.debug kernel: [30271.441928] wlan0: Limiting TX power to 17 dBm as advertised by 11:22:33:44:55:66
Wed Nov 1 20:11:50 2017 daemon.notice netifd: wwan (1998): udhcpc: started, v1.25.1
Wed Nov 1 20:11:50 2017 daemon.notice netifd: wwan (1998): udhcpc: sending discover
Wed Nov 1 20:11:53 2017 daemon.notice netifd: wwan (1998): udhcpc: sending discover
Wed Nov 1 20:11:54 2017 daemon.notice netifd: wwan (1998): udhcpc: sending select for 131.11.123.204
Wed Nov 1 20:11:54 2017 daemon.notice netifd: wwan (1998): udhcpc: lease of 131.11.123.204 obtained, lease time 1800
Wed Nov 1 20:11:54 2017 daemon.warn dnsmasq[1310]: no servers found in /tmp/resolv.conf.auto, will retry
Wed Nov 1 20:11:54 2017 daemon.notice netifd: Interface 'wwan' is now up
Wed Nov 1 20:11:54 2017 daemon.info dnsmasq[1310]: reading /tmp/resolv.conf.auto
Wed Nov 1 20:11:54 2017 daemon.info dnsmasq[1310]: using local addresses only for domain lan
Wed Nov 1 20:11:54 2017 daemon.info dnsmasq[1310]: using nameserver 131.11.123.2#53
Wed Nov 1 20:11:54 2017 daemon.info dnsmasq[1310]: using nameserver 131.11.124.2#53
Wed Nov 1 20:11:54 2017 user.notice firewall: Reloading firewall due to ifup of wwan (wlan0)
Wed Nov 1 20:11:55 2017 daemon.info odhcpd[824]: Using a RA lifetime of 0 seconds on br-lan
Wed Nov 1 20:17:42 2017 daemon.info hostapd: wlan1: STA 11:11:11:11:11:11 WPA: group key handshake completed (RSN)
Please help me. I will monitor this issue and make test if needed.