search

kaloz / mwlwifi

mac80211 driver for the Marvell 88W8864 802.11ac chip
395 stars 119 forks source link

Client stops receiving packets from router #210

Closed s-pimenta closed 7 years ago

s-pimenta commented 7 years ago

Laptop connected to 5GHz, watching some YouTube videos and the internet connection just stops... (laptop still says its connected) while this is occurring checked other devices connected also to 5GHz and no problem at all...

Reconnecting to the same wifi network solves the problem.

Running: WRT-3200ACM-EU 5GHz (channel 100), WPA2 802.1X (CCMP) EAP-PWD 2.4GHz (channel 11) WPA2 802.1X (CCMP) EAP-PWD LEDE Reboot SNAPSHOT r4114-6704410 / LuCI Master (git-17.130.58552-d04f667) Linux kernel: 4.9.20 mwlwifi: 2017-08-10

driver name: mwlwifi
chip type: 88W8964
hw version: 7
driver version: 10.3.4.0-20170810
firmware version: 0x09030007
power table loaded from dts: no
firmware region code: 0x30
mac address: 60:38:e0:b9:0b:2a
2g: disable
5g: enable
antenna: 4 4
irq number: 45
ap macid support: 0000ffff
sta macid support: 00010000
macid used: 00000001
radio: enable
iobase0: e0e00000
iobase1: e1080000
tx limit: 1024
rx limit: 16384

Log from the computer:

Aug 29 13:42:12 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 29 13:42:12 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 29 13:42:12 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 29 13:42:12 spimenta-laptop wpa_supplicant[353]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 29 13:42:12 spimenta-laptop wpa_supplicant[353]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 29 13:42:12 spimenta-laptop wpa_supplicant[353]:      65 2e 63 6f 6d                                    e.com
Aug 29 13:42:13 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 29 13:42:13 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:2a [PTK=CCMP GT
Aug 29 13:43:20 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 13:43:22 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 13:43:23 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 13:43:24 spimenta-laptop kernel: wlo1: deauthenticated from 60:38:e0:b9:0b:2a (Reason: 2=PREV_AUTH_NOT_VALID)
Aug 29 13:43:24 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:2a reason=2
Aug 29 13:43:24 spimenta-laptop NetworkManager[304]: <warn>  [1504010604.2921] sup-iface[0x7f48a4010150,wlo1]: connection disconnected (reason 2)
Aug 29 13:43:24 spimenta-laptop NetworkManager[304]: <info>  [1504010604.3160] device (wlo1): supplicant interface state: completed -> disconnected

Reason: 2=PREV_AUTH_NOT_VALID seems to be the source of the problem

yuhhaurlin commented 7 years ago
  1. Log from hostapd?
  2. Would this happen for PSK?
s-pimenta commented 7 years ago

Log from router: (LAPTOP MAC: 10:f0:05:08:ad:ea)

The router time is -1 hour off

Tue Aug 29 12:42:12 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Tue Aug 29 12:42:12 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 12:42:13 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session AC9CF00017CE8A56
Tue Aug 29 12:42:13 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 12:42:13 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Tue Aug 29 12:42:54 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 74:23:44:5a:a1:f6
Tue Aug 29 12:42:54 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 12:42:57 2017 daemon.info hostapd: wlan0: STA 74:23:44:5a:a1:f6 RADIUS: starting accounting session E0561876B0CFB9EA
Tue Aug 29 12:42:57 2017 daemon.info hostapd: wlan0: STA 74:23:44:5a:a1:f6 IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 12:42:59 2017 daemon.info hostapd: wlan0: STA 74:23:44:5a:a1:f6 WPA: pairwise key handshake completed (RSN)
Tue Aug 29 12:43:21 2017 daemon.err hostapd: nl80211: EAPOL TX: No message of desired type
Tue Aug 29 12:43:21 2017 daemon.info hostapd: wlan0: STA c0:ee:fb:20:60:c0 WPA: group key handshake completed (RSN)
Tue Aug 29 12:43:24 2017 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 74:23:44:5a:a1:f6
Tue Aug 29 12:43:24 2017 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 12:43:25 2017 kern.info kernel: [ 7284.541134] ieee80211 phy0: staid 1 deleted

PSK I don't know but I can try...

s-pimenta commented 7 years ago

I'm running freeradius in debug mode to see what happens

yuhhaurlin commented 7 years ago

You change group rekey to 60 seconds? Can you change log level to get more debug information?

yuhhaurlin commented 7 years ago

BTW, if possible, please just test with problem one.

s-pimenta commented 7 years ago

The problem happened again router not receiving packets, but while I was debugging the problem with an ethernet connected computer, the laptop after few minutes started to receiving packets again (maybe the laptop reconnects again?!)

(Linksys WRT3200ACM-EU) Router MAC ADDRESS: 60:38:e0:b9:0b:2a

Log from laptop

Aug 29 15:53:20 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 15:53:21 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 15:53:22 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 15:53:23 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 15:53:24 spimenta-laptop kernel: wlo1: deauthenticated from 60:38:e0:b9:0b:2a (Reason: 2=PREV_AUTH_NOT_VALID)
Aug 29 15:53:24 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:2a reason=2
Aug 29 15:53:24 spimenta-laptop NetworkManager[304]: <warn>  [1504018404.5164] sup-iface[0x7f48a4010330,wlo1]: connection disconnected (reason 2)

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Aug 29 15:53:24 spimenta-laptop NetworkManager[304]: <info>  [1504018404.5390] device (wlo1): supplicant interface state: completed -> disconnected
Aug 29 15:53:24 spimenta-laptop NetworkManager[304]: <info>  [1504018404.6219] device (wlo1): supplicant interface state: disconnected -> scanning
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: SME: Trying to authenticate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: authenticate with 60:38:e0:b9:0b:2a
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: send auth to 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 15:53:25 spimenta-laptop NetworkManager[304]: <info>  [1504018405.4859] device (wlo1): supplicant interface state: scanning -> authenticating
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: Trying to associate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: authenticated
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: associate with 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 15:53:25 spimenta-laptop NetworkManager[304]: <info>  [1504018405.5460] device (wlo1): supplicant interface state: authenticating -> associating
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: RX AssocResp from 60:38:e0:b9:0b:2a (capab=0x111 status=0 aid=2)
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: associated
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: Associated with 60:38:e0:b9:0b:2a
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 29 15:53:25 spimenta-laptop NetworkManager[304]: <info>  [1504018405.5612] device (wlo1): supplicant interface state: associating -> associated
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]:      65 2e 63 6f 6d                                    e.com
Aug 29 15:53:25 spimenta-laptop kernel: wlo1: Limiting TX power to 24 (27 - 3) dBm as advertised by 60:38:e0:b9:0b:2a
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:2a [PTK=CCMP GTK=CCMP]
Aug 29 15:53:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-CONNECTED - Connection to 60:38:e0:b9:0b:2a completed [id=0 id_str=]
Aug 29 15:53:25 spimenta-laptop NetworkManager[304]: <info>  [1504018405.7360] device (wlo1): supplicant interface state: associated -> completed

---------------------------------------------

Aug 29 15:55:06 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-48 noise=9999 txrate=433300
Aug 29 15:55:13 spimenta-laptop NetworkManager[304]: <info>  [1504018513.4597] connectivity: (wlo1) timed out
Aug 29 15:55:42 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 5
Aug 29 15:55:42 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 5
Aug 29 15:55:47 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 5
Aug 29 15:55:47 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 5
Aug 29 15:55:52 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 9
Aug 29 15:55:52 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 9
Aug 29 15:56:01 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 18
Aug 29 15:56:01 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 18
Aug 29 15:56:19 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 15
Aug 29 15:56:19 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 15
Aug 29 15:56:34 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 9
Aug 29 15:56:34 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 9
Aug 29 15:56:43 spimenta-laptop dhclient[291]: No DHCPOFFERS received.
Aug 29 15:56:43 spimenta-laptop dhclient[291]: No DHCPOFFERS received.
Aug 29 15:56:43 spimenta-laptop dhclient[291]: No working leases in persistent database - sleeping.
Aug 29 15:56:43 spimenta-laptop dhclient[291]: No working leases in persistent database - sleeping.
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: disassociated from 60:38:e0:b9:0b:2a (Reason: 4=DISASSOC_DUE_TO_INACTIVITY)
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:2a reason=4
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: SME: Trying to authenticate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 15:58:25 spimenta-laptop NetworkManager[304]: <warn>  [1504018705.6501] sup-iface[0x7f48a4010330,wlo1]: connection disconnected (reason 4)

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Aug 29 15:58:25 spimenta-laptop kernel: wlo1: authenticate with 60:38:e0:b9:0b:2a
Aug 29 15:58:25 spimenta-laptop NetworkManager[304]: <info>  [1504018705.6565] device (wlo1): supplicant interface state: completed -> authenticating
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: Trying to associate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: send auth to 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: authenticated
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: associate with 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 15:58:25 spimenta-laptop NetworkManager[304]: <info>  [1504018705.6639] device (wlo1): supplicant interface state: authenticating -> associating
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: RX AssocResp from 60:38:e0:b9:0b:2a (capab=0x111 status=0 aid=2)
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: associated
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: Associated with 60:38:e0:b9:0b:2a
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 29 15:58:25 spimenta-laptop NetworkManager[304]: <info>  [1504018705.6776] device (wlo1): supplicant interface state: associating -> associated
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]:      65 2e 63 6f 6d                                    e.com
Aug 29 15:58:25 spimenta-laptop kernel: wlo1: Limiting TX power to 24 (27 - 3) dBm as advertised by 60:38:e0:b9:0b:2a
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:2a [PTK=CCMP GTK=CCMP]
Aug 29 15:58:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-CONNECTED - Connection to 60:38:e0:b9:0b:2a completed [id=0 id_str=]

freeradius in debug mode seems to not give anything useful to debug this problem.

Log from router: (router log is now with correct Time zone as Laptop)

Tue Aug 29 15:53:24 2017 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 15:53:25 2017 kern.info kernel: [15084.641567] ieee80211 phy0: staid 2 deleted
Tue Aug 29 15:53:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: associated (aid 2)
Tue Aug 29 15:53:25 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Tue Aug 29 15:53:25 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 15:53:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Tue Aug 29 15:53:25 2017 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 15:53:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session C51FC98F50B657DE
Tue Aug 29 15:53:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 15:53:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: authenticated
Tue Aug 29 15:53:26 2017 kern.info kernel: [15085.223703] ieee80211 phy0: staid 2 deleted
Tue Aug 29 15:56:30 2017 user.warn igmpproxy[3113]: MRT_DEL_MFC; Errno(2): No such file or directory
Tue Aug 29 15:58:25 2017 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 15:58:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: disassociated due to inactivity

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ THIS Match with LAPTOP LOG

Tue Aug 29 15:58:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: associated (aid 2)
Tue Aug 29 15:58:25 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Tue Aug 29 15:58:25 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 15:58:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Tue Aug 29 15:58:25 2017 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 15:58:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session C51FC98F50B657DE
Tue Aug 29 15:58:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 15:58:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: authenticated

also see this in router syslog: (but I don't have any with ip: 188.83.231.133)

Tue Aug 29 15:45:16 2017 daemon.notice netifd: wan (1666): udhcpc: sending renew
Tue Aug 29 15:45:16 2017 daemon.notice netifd: wan (1666): udhcpc: lease of 188.83.231.133 obtained, lease time 3600
s-pimenta commented 7 years ago

You change group rekey to 60 seconds? Can you change log level to get more debug information?

How I do that?

s-pimenta commented 7 years ago

Just happened the same problem, but I discovered something...

When I was browsing the Internet and the page load fails (time 16:58) in the logs doesn't see nothing from on the logs from laptop and router:

Laptop log (when the problem happened at 16:58):

Aug 29 16:58:28 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]:      65 2e 63 6f 6d                                    e.com
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 29 16:58:29 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:2a [PTK=CCMP GTK=CCMP]

Router log (when the problem happened at 16:58):

Tue Aug 29 16:58:28 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Tue Aug 29 16:58:28 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 16:58:29 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session C51FC98F50B657DE
Tue Aug 29 16:58:29 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 16:58:29 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)

Then at 17:03 (the laptop is still without internet) got this from laptop log:

Aug 29 17:03:20 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 17:03:21 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 17:03:22 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 17:03:23 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:2a [GTK=CCMP]
Aug 29 17:03:24 spimenta-laptop kernel: wlo1: deauthenticated from 60:38:e0:b9:0b:2a (Reason: 2=PREV_AUTH_NOT_VALID)
Aug 29 17:03:24 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:2a reason=2
Aug 29 17:03:24 spimenta-laptop NetworkManager[304]: <warn>  [1504022604.3332] sup-iface[0x7f48a4010330,wlo1]: connection disconnected (reason 2)

^^^^^^^^^^^^^^^^^^ SAME REASON (Reason: 2=PREV_AUTH_NOT_VALID) ^^^^^^^^^^^^^^^^^^^^

Aug 29 17:03:24 spimenta-laptop NetworkManager[304]: <info>  [1504022604.3552] device (wlo1): supplicant interface state: completed -> disconnected
Aug 29 17:03:24 spimenta-laptop NetworkManager[304]: <info>  [1504022604.4391] device (wlo1): supplicant interface state: disconnected -> scanning
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: SME: Trying to authenticate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: authenticate with 60:38:e0:b9:0b:2a
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: send auth to 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 17:03:25 spimenta-laptop NetworkManager[304]: <info>  [1504022605.3072] device (wlo1): supplicant interface state: scanning -> authenticating
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: Trying to associate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: authenticated
Aug 29 17:03:25 spimenta-laptop NetworkManager[304]: <info>  [1504022605.3530] device (wlo1): supplicant interface state: authenticating -> associating
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: associate with 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: RX AssocResp from 60:38:e0:b9:0b:2a (capab=0x111 status=0 aid=2)
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: Associated with 60:38:e0:b9:0b:2a
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: associated
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 29 17:03:25 spimenta-laptop NetworkManager[304]: <info>  [1504022605.3698] device (wlo1): supplicant interface state: associating -> associated
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]:      65 2e 63 6f 6d                                    e.com
Aug 29 17:03:25 spimenta-laptop kernel: wlo1: Limiting TX power to 24 (27 - 3) dBm as advertised by 60:38:e0:b9:0b:2a
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:2a [PTK=CCMP GTK=CCMP]
Aug 29 17:03:25 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-CONNECTED - Connection to 60:38:e0:b9:0b:2a completed [id=0 id_str=]
Aug 29 17:03:25 spimenta-laptop NetworkManager[304]: <info>  [1504022605.5447] device (wlo1): supplicant interface state: associated -> completed

And the router log got whis (at 17:03)

Tue Aug 29 17:03:20 2017 daemon.info hostapd: wlan0: STA 74:23:44:5a:a1:f6 WPA: group key handshake completed (RSN)
Tue Aug 29 17:03:24 2017 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 17:03:25 2017 kern.info kernel: [19284.377733] ieee80211 phy0: staid 2 deleted
Tue Aug 29 17:03:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: associated (aid 2)
Tue Aug 29 17:03:25 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Tue Aug 29 17:03:25 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 17:03:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Tue Aug 29 17:03:25 2017 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 17:03:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session C51FC98F50B657DE
Tue Aug 29 17:03:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 17:03:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: authenticated
Tue Aug 29 17:03:26 2017 kern.info kernel: [19285.723712] ieee80211 phy0: staid 2 deleted

Then WITHOUT manually reconnect to the wifi network, at 17:08 got Internet connection!

The laptop says this:

Aug 29 17:08:00 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 5
Aug 29 17:08:00 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 5
Aug 29 17:08:05 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 7
Aug 29 17:08:05 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 7
Aug 29 17:08:12 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 12
Aug 29 17:08:12 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 12
Aug 29 17:08:24 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 12
Aug 29 17:08:24 spimenta-laptop dhclient[291]: DHCPDISCOVER on eno1 to 255.255.255.255 port 67 interval 12
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: deauthenticated from 60:38:e0:b9:0b:2a (Reason: 7=CLASS3_FRAME_FROM_NONASSOC_STA)
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:2a reason=7

^^^^^^^^^^^^ Different reason (Reason: 7=CLASS3_FRAME_FROM_NONASSOC_STA) ^^^^^^^^^^^^^^^^^

Aug 29 17:08:26 spimenta-laptop NetworkManager[304]: <warn>  [1504022906.6938] sup-iface[0x7f48a4010330,wlo1]: connection disconnected (reason 7)
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: SME: Trying to authenticate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: authenticate with 60:38:e0:b9:0b:2a
Aug 29 17:08:26 spimenta-laptop NetworkManager[304]: <info>  [1504022906.7294] device (wlo1): supplicant interface state: completed -> authenticating
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: Trying to associate with 60:38:e0:b9:0b:2a (SSID='dd-wrt 5GHz' freq=5500 MHz)
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: send auth to 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: authenticated
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: associate with 60:38:e0:b9:0b:2a (try 1/3)
Aug 29 17:08:26 spimenta-laptop NetworkManager[304]: <info>  [1504022906.7363] device (wlo1): supplicant interface state: authenticating -> associating
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: RX AssocResp from 60:38:e0:b9:0b:2a (capab=0x111 status=0 aid=2)
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: Associated with 60:38:e0:b9:0b:2a
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: associated
Aug 29 17:08:26 spimenta-laptop NetworkManager[304]: <info>  [1504022906.7487] device (wlo1): supplicant interface state: associating -> associated
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]:      65 2e 63 6f 6d                                    e.com
Aug 29 17:08:26 spimenta-laptop kernel: wlo1: Limiting TX power to 24 (27 - 3) dBm as advertised by 60:38:e0:b9:0b:2a
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:2a [PTK=CCMP GTK=CCMP]
Aug 29 17:08:26 spimenta-laptop wpa_supplicant[353]: wlo1: CTRL-EVENT-CONNECTED - Connection to 60:38:e0:b9:0b:2a completed [id=0 id_str=]
Aug 29 17:08:26 spimenta-laptop NetworkManager[304]: <info>  [1504022906.9184] device (wlo1): supplicant interface state: associated -> completed

The router got this (at 17:08)

Tue Aug 29 17:08:25 2017 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 17:08:25 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: disassociated due to inactivity
Tue Aug 29 17:08:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

^^^^^^^^^^^^^^ The reason is (disassociated due to inactivity) ^^^^^^^^^^^^^^^^^^^^^^^^^^

Tue Aug 29 17:08:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: associated (aid 2)
Tue Aug 29 17:08:26 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Tue Aug 29 17:08:26 2017 daemon.notice hostapd: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Tue Aug 29 17:08:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Tue Aug 29 17:08:26 2017 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 10:f0:05:08:ad:ea
Tue Aug 29 17:08:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session A86CB665E7BE67BC
Tue Aug 29 17:08:26 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Tue Aug 29 17:08:27 2017 daemon.info hostapd: wlan0: STA 10:f0:05:08:ad:ea IEEE 802.11: authenticated

When I lost connection with router seems the logs mean nothing, but when time passes by (still without connection) something happens...

I hope this time will help to track down the problem I face..

yuhhaurlin commented 7 years ago

It looks like it is related to group rekey. From client, it receives three group rekey, but it seems like AP does not receive the reply （You should change log level of hostapd to get more debug messages）. I will let you know how to disable group rekey tomorrow to make sure what I suspect. If yes, I will come out debug image to track this problem. Can you help to check if you can find group rekey complete for this client on the log of hostapd. Thanks.

yuhhaurlin commented 7 years ago

You can add "option wpa_group_rekey '0'" to /etc/config/wireless to disable group rekey. You need to use "wifi up" to let the setting work.

If the setting works, you will not see group rekey related messages in your client log.

s-pimenta commented 7 years ago

I've put hostapd _logger_sysloglevel and _logger_stdoutlevel to 0 to have max debug verbosity

yuhhaurlin commented 7 years ago

Please help to check if disable group rekey can resolve the problem for this specific client?

yuhhaurlin commented 7 years ago

You need to modify /etc/config/wireless and add "option wpa_group_rekey '0'" to the configuration of the AP you used. You can reboot or issue "wifi up" to let it work. You can check /var/run/hostapd-phy0.conf or /var/run/hostapd-phy1.conf (depends on which module you used) to see if this command is added. If this setting works, from the log of this specific client, you won't see messages related to group rekey. Please let me know if this way can work around the problem with this specific client. Thanks.

s-pimenta commented 7 years ago

Now in 2.4GHz

Lost connection (13:08)

Laptop Log:

Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]:      65 2e 63 6f 6d                                    e.com
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 31 13:08:40 spimenta-laptop NetworkManager[294]: <info>  [1504181320.7240] device (wlo1): supplicant interface state: completed -> 4-way handshake
Aug 31 13:08:40 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:29 [PTK=CCMP GTK=CCMP]
Aug 31 13:08:40 spimenta-laptop NetworkManager[294]: <info>  [1504181320.7354] device (wlo1): supplicant interface state: 4-way handshake -> completed

Router Log:

Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: event 5 notification
Thu Aug 31 13:08:40 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Thu Aug 31 13:08:40 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 218)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=218 len=12) from STA: EAP Response-Identity (1)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: STA identity 'pimenta'
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server

Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=219 len=36) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 219)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=219 len=22) from STA: EAP Response-unknown (52)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server

Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.03 sec
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=220 len=102) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 220)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=220 len=102) from STA: EAP Response-unknown (52)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server

Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.02 sec
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=221 len=38) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 221)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=221 len=38) from STA: EAP Response-unknown (52)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server

Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.02 sec
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=3 id=221 len=4) from RADIUS server: EAP Success
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 221)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authorizing port
Thu Aug 31 13:08:40 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session 5BE939603557707C
Thu Aug 31 13:08:40 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/4 msg of 4-Way Handshake
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (2/4 Pairwise)
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 3/4 msg of 4-Way Handshake
Thu Aug 31 13:08:40 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (4/4 Pairwise)
Thu Aug 31 13:08:40 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)

Still without connection (13:16):

Laptop log:

Aug 31 13:16:49 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:29 [GTK=CCMP]
Aug 31 13:16:49 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:29 [GTK=CCMP]
Aug 31 13:16:50 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:29 [GTK=CCMP]
Aug 31 13:16:51 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Group rekeying completed with 60:38:e0:b9:0b:29 [GTK=CCMP]

-------------->>>>> Same reason [PREV_AUTH_NOT_VALID] <<<<---------------
Aug 31 13:16:52 spimenta-laptop kernel: wlo1: deauthenticated from 60:38:e0:b9:0b:29 (Reason: 2=PREV_AUTH_NOT_VALID)
Aug 31 13:16:53 spimenta-laptop wpa_supplicant[1870]: nl80211: Was expecting local deauth but got another disconnect event first
Aug 31 13:16:53 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:29 reason=2
Aug 31 13:16:53 spimenta-laptop NetworkManager[294]: <warn>  [1504181813.0441] sup-iface[0x55c0c9ba5be0,wlo1]: connection disconnected (reason 2)
------------------>>>>>>><<<<<<<<<---------------------

Aug 31 13:16:53 spimenta-laptop NetworkManager[294]: <info>  [1504181813.0805] device (wlo1): supplicant interface state: completed -> disconnected
Aug 31 13:16:53 spimenta-laptop NetworkManager[294]: <info>  [1504181813.1497] device (wlo1): supplicant interface state: disconnected -> scanning
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: SME: Trying to authenticate with 60:38:e0:b9:0b:29 (SSID='dd-wrt 2.4GHz' freq=2462 MHz)
Aug 31 13:16:56 spimenta-laptop kernel: wlo1: authenticate with 60:38:e0:b9:0b:29
Aug 31 13:16:56 spimenta-laptop NetworkManager[294]: <info>  [1504181816.6252] device (wlo1): supplicant interface state: scanning -> authenticating
Aug 31 13:16:56 spimenta-laptop kernel: wlo1: send auth to 60:38:e0:b9:0b:29 (try 1/3)
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: Trying to associate with 60:38:e0:b9:0b:29 (SSID='dd-wrt 2.4GHz' freq=2462 MHz)
Aug 31 13:16:56 spimenta-laptop kernel: wlo1: authenticated
Aug 31 13:16:56 spimenta-laptop kernel: wlo1: associate with 60:38:e0:b9:0b:29 (try 1/3)
Aug 31 13:16:56 spimenta-laptop NetworkManager[294]: <info>  [1504181816.6408] device (wlo1): supplicant interface state: authenticating -> associating
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: Associated with 60:38:e0:b9:0b:29
Aug 31 13:16:56 spimenta-laptop kernel: wlo1: RX AssocResp from 60:38:e0:b9:0b:29 (capab=0x431 status=0 aid=4)
Aug 31 13:16:56 spimenta-laptop kernel: wlo1: associated
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 31 13:16:56 spimenta-laptop NetworkManager[294]: <info>  [1504181816.6550] device (wlo1): supplicant interface state: associating -> associated
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]:      65 2e 63 6f 6d                                    e.com
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:29 [PTK=CCMP GTK=CCMP]
Aug 31 13:16:56 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-CONNECTED - Connection to 60:38:e0:b9:0b:29 completed [id=0 id_str=]
Aug 31 13:16:56 spimenta-laptop NetworkManager[294]: <info>  [1504181816.8534] device (wlo1): supplicant interface state: associated -> completed

Router log:

Thu Aug 31 13:16:49 2017 daemon.debug hostapd: wlan1: WPA rekeying GTK
Thu Aug 31 13:16:49 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: sending 1/2 msg of Group Key Handshake
Thu Aug 31 13:16:49 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/2 msg of Group Key Handshake
Thu Aug 31 13:16:49 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: received EAPOL-Key frame (2/2 Group)
Thu Aug 31 13:16:49 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: group key handshake completed (RSN)
Thu Aug 31 13:16:49 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: EAPOL-Key timeout
Thu Aug 31 13:16:49 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/2 msg of Group Key Handshake
Thu Aug 31 13:16:50 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: EAPOL-Key timeout
Thu Aug 31 13:16:50 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/2 msg of Group Key Handshake
Thu Aug 31 13:16:51 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: EAPOL-Key timeout
Thu Aug 31 13:16:51 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/2 msg of Group Key Handshake
Thu Aug 31 13:16:52 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: EAPOL-Key timeout

------------------------<<<<<<<<<<< WPA: WPA_PTK: sm->Disconnect >>>>>>>>>>>-------------------
Thu Aug 31 13:16:52 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: WPA_PTK: sm->Disconnect
Thu Aug 31 13:16:52 2017 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea

Thu Aug 31 13:16:52 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: event 3 notification
Thu Aug 31 13:16:54 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DEAUTHENTICATE.indication(10:f0:05:08:ad:ea, 2)
Thu Aug 31 13:16:54 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)
Thu Aug 31 13:16:54 2017 kern.info kernel: [ 4821.995249] ieee80211 phy1: staid 4 deleted
---------------------<<<<<<<<<<<<<<<<<>>>>>>>>>>>>>>>>>>----------------------

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: authentication OK (open system)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: event 0 notification
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-AUTHENTICATE.indication(10:f0:05:08:ad:ea, OPEN_SYSTEM)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: association OK (aid 4)
Thu Aug 31 13:16:56 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: associated (aid 4)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-ASSOCIATE.indication(10:f0:05:08:ad:ea)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: event 1 notification
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: unauthorizing port

Thu Aug 31 13:16:56 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Thu Aug 31 13:16:56 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 188)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=188 len=12) from STA: EAP Response-Identity (1)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: STA identity 'pimenta'

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=189 len=36) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 189)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=189 len=22) from STA: EAP Response-unknown (52)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.08 sec
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=190 len=102) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 190)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=190 len=102) from STA: EAP Response-unknown (52)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=191 len=38) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 191)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=191 len=38) from STA: EAP Response-unknown (52)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=3 id=191 len=4) from RADIUS server: EAP Success
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 191)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/4 msg of 4-Way Handshake
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (2/4 Pairwise)
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 3/4 msg of 4-Way Handshake
Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (4/4 Pairwise)
Thu Aug 31 13:16:56 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Thu Aug 31 13:16:56 2017 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 10:f0:05:08:ad:ea

Thu Aug 31 13:16:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authorizing port
Thu Aug 31 13:16:56 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session 5BE939603557707C
Thu Aug 31 13:16:56 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Thu Aug 31 13:16:57 2017 kern.info kernel: [ 4824.292391] ieee80211 phy1: staid 2 deleted
Thu Aug 31 13:16:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DEAUTHENTICATE.indication(10:f0:05:08:ad:ea, 2)
Thu Aug 31 13:16:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)
Thu Aug 31 13:16:57 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: authenticated

Now automatically got connection: (13:21)

Laptop log:

I don't know if this mean anything (at this time no log from router)

Aug 31 13:19:13 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-46 noise=9999 txrate=72200

Got connection here:

Aug 31 13:21:57 spimenta-laptop kernel: wlo1: deauthenticated from 60:38:e0:b9:0b:29 (Reason: 7=CLASS3_FRAME_FROM_NONASSOC_STA)
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-DISCONNECTED bssid=60:38:e0:b9:0b:29 reason=7
Aug 31 13:21:57 spimenta-laptop NetworkManager[294]: <warn>  [1504182117.7615] sup-iface[0x55c0c9ba5be0,wlo1]: connection disconnected (reason 7)

<<<<<<<<<<<<<<<<<<<<<<<< CLASS3_FRAME_FROM_NONASSOC_STA >>>>>>>>>>>>>>>>>>>>>

Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: SME: Trying to authenticate with 60:38:e0:b9:0b:29 (SSID='dd-wrt 2.4GHz' freq=2462 MHz)
Aug 31 13:21:57 spimenta-laptop kernel: wlo1: authenticate with 60:38:e0:b9:0b:29
Aug 31 13:21:57 spimenta-laptop NetworkManager[294]: <info>  [1504182117.7877] device (wlo1): supplicant interface state: completed -> authenticating
Aug 31 13:21:57 spimenta-laptop kernel: wlo1: send auth to 60:38:e0:b9:0b:29 (try 1/3)
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: Trying to associate with 60:38:e0:b9:0b:29 (SSID='dd-wrt 2.4GHz' freq=2462 MHz)
Aug 31 13:21:57 spimenta-laptop kernel: wlo1: authenticated
Aug 31 13:21:57 spimenta-laptop kernel: wlo1: associate with 60:38:e0:b9:0b:29 (try 1/3)
Aug 31 13:21:57 spimenta-laptop NetworkManager[294]: <info>  [1504182117.7971] device (wlo1): supplicant interface state: authenticating -> associating
Aug 31 13:21:57 spimenta-laptop kernel: wlo1: RX AssocResp from 60:38:e0:b9:0b:29 (capab=0x431 status=0 aid=2)
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: Associated with 60:38:e0:b9:0b:29
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 31 13:21:57 spimenta-laptop kernel: wlo1: associated
Aug 31 13:21:57 spimenta-laptop NetworkManager[294]: <info>  [1504182117.8142] device (wlo1): supplicant interface state: associating -> associated
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]:      65 2e 63 6f 6d                                    e.com
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 31 13:21:57 spimenta-laptop NetworkManager[294]: <info>  [1504182117.9377] device (wlo1): supplicant interface state: associated -> 4-way handshake
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:29 [PTK=CCMP GTK=CCMP]
Aug 31 13:21:57 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-CONNECTED - Connection to 60:38:e0:b9:0b:29 completed [id=0 id_str=]
Aug 31 13:21:57 spimenta-laptop NetworkManager[294]: <info>  [1504182117.9481] device (wlo1): supplicant interface state: 4-way handshake -> completed

Router log:

Thu Aug 31 13:21:56 2017 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 10:f0:05:08:ad:ea
Thu Aug 31 13:21:56 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: disassociated due to inactivity
Thu Aug 31 13:21:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DISASSOCIATE.indication(10:f0:05:08:ad:ea, 4)
Thu Aug 31 13:21:56 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)
Thu Aug 31 13:21:57 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

^^^^^^^^^^^^^^^^^^^^^^ deauthenticated due to inactivity ^^^^^^^^^^^^^^^^^^^^^

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DEAUTHENTICATE.indication(10:f0:05:08:ad:ea, 2)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: authentication OK (open system)

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-AUTHENTICATE.indication(10:f0:05:08:ad:ea, OPEN_SYSTEM)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: association OK (aid 2)

Thu Aug 31 13:21:57 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: associated (aid 2)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-ASSOCIATE.indication(10:f0:05:08:ad:ea)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea MLME: MLME-DELETEKEYS.request(10:f0:05:08:ad:ea)

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: event 1 notification
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: start authentication
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: start authentication
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: unauthorizing port

Thu Aug 31 13:21:57 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Thu Aug 31 13:21:57 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 236)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=236 len=12) from STA: EAP Response-Identity (1)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: STA identity 'pimenta'
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=237 len=36) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 237)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=237 len=22) from STA: EAP Response-unknown (52)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=238 len=102) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 238)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=238 len=102) from STA: EAP Response-unknown (52)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.03 sec
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=239 len=38) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 239)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=239 len=38) from STA: EAP Response-unknown (52)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.02 sec
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=3 id=239 len=4) from RADIUS server: EAP Success
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 239)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/4 msg of 4-Way Handshake
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (2/4 Pairwise)
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 3/4 msg of 4-Way Handshake
Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (4/4 Pairwise)
Thu Aug 31 13:21:57 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)
Thu Aug 31 13:21:57 2017 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 10:f0:05:08:ad:ea

Thu Aug 31 13:21:57 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authorizing port
Thu Aug 31 13:21:57 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session 276D74671487FDA1
Thu Aug 31 13:21:57 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Thu Aug 31 13:21:58 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: authenticated

I will now change the _wpa_grouprekey '0' to see if this temporary work around solves the problem...

yuhhaurlin commented 7 years ago

Same as previous log, client shows group rekey completes, but AP does not get reply, so it tries a lot of times, then AP disconnects this client.

This log level can't display group rekey timeout in log of router. However, if group rekey is all right, you should see group rekey complete with this client in log of router.

s-pimenta commented 7 years ago

This log level can't display group rekey timeout in log of router.

How do I change that?

yuhhaurlin commented 7 years ago

Please try the option directly.

s-pimenta commented 7 years ago

Seems to be activated:

root@LEDE:~# cat /var/run/hostapd-phy0.conf 
driver=nl80211
logger_syslog=127
logger_syslog_level=0
logger_stdout=127
logger_stdout_level=0
country_code=FR
ieee80211d=1
ieee80211h=1
hw_mode=a
beacon_int=100
channel=100

ieee80211n=1
ht_coex=0
ht_capab=[HT40+][LDPC][SHORT-GI-20][SHORT-GI-40][MAX-AMSDU-7935][DSSS_CCK-40]
vht_oper_chwidth=1
vht_oper_centr_freq_seg0_idx=106
ieee80211ac=1
vht_capab=[RXLDPC][SHORT-GI-80][SHORT-GI-160][SU-BEAMFORMER][SU-BEAMFORMEE][RX-ANTENNA-PATTERN][TX-ANTENNA-PATTERN][RX-STBC-1][VHT160][MAX-MPDU-11454][MAX-A-MPDU-LEN-EXP7]

interface=wlan0
ctrl_interface=/var/run/hostapd
ap_isolate=1
disassoc_low_ack=1
preamble=1
wmm_enabled=1
ignore_broadcast_ssid=0
uapsd_advertisement_enabled=1
wpa_group_rekey=0
auth_server_addr=192.168.1.209
auth_server_port=1812
auth_server_shared_secret=MB49GLz94P74Sn6PJwqH
eapol_key_index_workaround=1
ieee8021x=1
auth_algs=1
wpa=2
wpa_pairwise=CCMP
ssid=dd-wrt 5GHz
bridge=br-lan
wpa_key_mgmt=WPA-EAP
okc=0
disable_pmksa_caching=1
bssid=60:38:e0:b9:0b:2a
yuhhaurlin commented 7 years ago

Yes.

s-pimenta commented 7 years ago

The problem still happens, and worse will not reconnect (waited about 45min, and no automatic reconnect), need to manually reconnect to the network.

(16:00) Before lost connection

Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: authentication OK (open system)
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-AUTHENTICATE.indication(c0:ee:fb:20:60:c0, OPEN_SYSTEM)
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-DELETEKEYS.request(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: association OK (aid 3)
Thu Aug 31 16:00:09 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: associated (aid 3)
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-ASSOCIATE.indication(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-DELETEKEYS.request(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: event 1 notification
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: start authentication
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: start authentication
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: unauthorizing port
Thu Aug 31 16:00:09 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED c0:ee:fb:20:60:c0
Thu Aug 31 16:00:09 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Thu Aug 31 16:00:09 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 35)
Thu Aug 31 16:00:10 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: event 3 notification
Thu Aug 31 16:00:10 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: deauthenticated
Thu Aug 31 16:00:10 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-DEAUTHENTICATE.indication(c0:ee:fb:20:60:c0, 3)
Thu Aug 31 16:00:10 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-DELETEKEYS.request(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:10 2017 kern.info kernel: [14617.033372] ieee80211 phy1: staid 3 deleted
Thu Aug 31 16:00:10 2017 daemon.notice hostapd: handle_auth_cb: STA c0:ee:fb:20:60:c0 not found
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: authentication OK (open system)
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-AUTHENTICATE.indication(c0:ee:fb:20:60:c0, OPEN_SYSTEM)
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-DELETEKEYS.request(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: association OK (aid 3)
Thu Aug 31 16:00:23 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: associated (aid 3)
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-ASSOCIATE.indication(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 MLME: MLME-DELETEKEYS.request(c0:ee:fb:20:60:c0)
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: event 1 notification
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: start authentication
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: start authentication
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: unauthorizing port
Thu Aug 31 16:00:23 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED c0:ee:fb:20:60:c0
Thu Aug 31 16:00:23 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Thu Aug 31 16:00:23 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 148)
Thu Aug 31 16:00:24 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: authenticated
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 148)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: received EAP packet (code=2 id=148 len=12) from STA: EAP Response-Identity (1)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: STA identity 'pimenta'
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: decapsulated EAP packet (code=1 id=149 len=36) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 149)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: received EAP packet (code=2 id=149 len=22) from STA: EAP Response-unknown (52)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: decapsulated EAP packet (code=1 id=150 len=102) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 150)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: received EAP packet (code=2 id=150 len=102) from STA: EAP Response-unknown (52)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.02 sec
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: decapsulated EAP packet (code=1 id=151 len=38) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 151)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: received EAP packet (code=2 id=151 len=38) from STA: EAP Response-unknown (52)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: decapsulated EAP packet (code=3 id=151 len=4) from RADIUS server: EAP Success
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: Sending EAP Packet (identifier 151)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: sending 1/4 msg of 4-Way Handshake
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: received EAPOL-Key frame (2/4 Pairwise)
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: sending 3/4 msg of 4-Way Handshake
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: received EAPOL-Key frame (4/4 Pairwise)
Thu Aug 31 16:00:26 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 WPA: pairwise key handshake completed (RSN)
Thu Aug 31 16:00:26 2017 daemon.notice hostapd: wlan1: AP-STA-CONNECTED c0:ee:fb:20:60:c0
Thu Aug 31 16:00:26 2017 daemon.debug hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: authorizing port
Thu Aug 31 16:00:26 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 RADIUS: starting accounting session CB28C150B38A793B
Thu Aug 31 16:00:26 2017 daemon.info hostapd: wlan1: STA c0:ee:fb:20:60:c0 IEEE 802.1X: authenticated - EAP type: 52 (unknown)

Laptop log:

At 16:00 NOTHING was found on Laptop log...

(16:11) lost connection

Router Log:

Thu Aug 31 16:11:45 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: event 5 notification
Thu Aug 31 16:11:45 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED 10:f0:05:08:ad:ea
Thu Aug 31 16:11:45 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Thu Aug 31 16:11:45 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 130)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=130 len=12) from STA: EAP Response-Identity (1)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: STA identity 'pimenta'
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.01 sec
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=131 len=36) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 131)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=131 len=22) from STA: EAP Response-unknown (52)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.03 sec
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=132 len=102) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 132)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=132 len=102) from STA: EAP Response-unknown (52)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.02 sec
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=1 id=133 len=38) from RADIUS server: EAP-Request-unknown (52)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 133)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: received EAP packet (code=2 id=133 len=38) from STA: EAP Response-unknown (52)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.11: binding station to interface 'wlan1'
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: decapsulated EAP packet (code=3 id=133 len=4) from RADIUS server: EAP Success
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: Sending EAP Packet (identifier 133)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authorizing port
Thu Aug 31 16:11:46 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea RADIUS: starting accounting session 06BA44817CB84F79
Thu Aug 31 16:11:46 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 1/4 msg of 4-Way Handshake
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (2/4 Pairwise)
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: sending 3/4 msg of 4-Way Handshake
Thu Aug 31 16:11:46 2017 daemon.debug hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: received EAPOL-Key frame (4/4 Pairwise)
Thu Aug 31 16:11:46 2017 daemon.info hostapd: wlan1: STA 10:f0:05:08:ad:ea WPA: pairwise key handshake completed (RSN)

Laptop log:

Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=52
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 52 (PWD) selected
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]: EAP-PWD (peer): server sent id of - hexdump_ascii(len=21):
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]:      74 68 65 73 65 72 76 65 72 40 65 78 61 6d 70 6c   theserver@exampl
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]:      65 2e 63 6f 6d                                    e.com
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]: wlo1: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 31 16:11:46 spimenta-laptop NetworkManager[294]: <info>  [1504192306.1807] device (wlo1): supplicant interface state: completed -> 4-way handshake
Aug 31 16:11:46 spimenta-laptop wpa_supplicant[1870]: wlo1: WPA: Key negotiation completed with 60:38:e0:b9:0b:29 [PTK=CCMP GTK=CCMP]
Aug 31 16:11:46 spimenta-laptop NetworkManager[294]: <info>  [1504192306.1943] device (wlo1): supplicant interface state: 4-way handshake -> completed

After lost connection nothing has been found in the logs (both router and laptop), until I try to reconnect manually

Only found this in the laptop

Aug 31 16:28:44 spimenta-laptop NetworkManager[294]: <info>  [1504193324.0202] connectivity: (wlo1) timed out
Aug 31 16:33:44 spimenta-laptop NetworkManager[294]: <info>  [1504193624.0218] connectivity: (wlo1) timed out
yuhhaurlin commented 7 years ago

From the log, I can't find disconnection. Can you check if ping to router is all right?

s-pimenta commented 7 years ago

I forgot to post the ping, says Host unreachable

As said in the issue title, no packets are received...

When this happens and this client is the only one connected to the router, I can see the wifi activity light just stays ON, never blinks anymore (pinging doesn't make to blink)

yuhhaurlin commented 7 years ago
  1. Does this problem also happen with stock firmware?
  2. Can you help to check if this client works well with other AP? If yes, let me know which client you use and driver version. If not, can you check if this is a known issue of this client and there is updated driver for it to resolve this problem. Thanks.
s-pimenta commented 7 years ago

  1. I will test with stock OEM firmware

  2. No, never had wifi issues with this laptop connected with other Acess Points. The laptop is new (3 months) its an intel wifi AC card 1X1, using Arch Linux... so definitely using lastest wifi drivers and lastest kernel (4.12)

yuhhaurlin commented 7 years ago

Except for this client, all other clients are all right?

s-pimenta commented 7 years ago

@yuhhaurlin

Except for this client, all other clients are all right?

No, also happened to other clients... With the other client loss of Internet connection (but tablet stills says is connected to the Wifi network) I noticed that at exacly 1 hour after first authentication to the network the problem happens...

I have the option wpa_group_rekey '0' enabled on both radios... I will remove that option, and do some more tests...

Log from the different client that happened the problem:

When the client connects to the network (19:51:38)

Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: authentication OK (open system)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 MLME: MLME-AUTHENTICATE.indication(f8:32:e4:0f:6c:c9, OPEN_SYSTEM)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 MLME: MLME-DELETEKEYS.request(f8:32:e4:0f:6c:c9)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: association OK (aid 1)
Fri Sep  1 19:51:38 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: associated (aid 1)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 MLME: MLME-ASSOCIATE.indication(f8:32:e4:0f:6c:c9)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 MLME: MLME-DELETEKEYS.request(f8:32:e4:0f:6c:c9)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: binding station to interface 'wlan1'
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: event 1 notification
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: start authentication
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: start authentication
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: unauthorizing port
Fri Sep  1 19:51:38 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED f8:32:e4:0f:6c:c9
Fri Sep  1 19:51:38 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 171)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=171 len=12) from STA: EAP Response-Identity (1)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: STA identity 'pimenta'
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=1 id=172 len=36) from RADIUS server: EAP-Request-unknown (52)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 172)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=172 len=22) from STA: EAP Response-unknown (52)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.06 sec
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=1 id=173 len=102) from RADIUS server: EAP-Request-unknown (52)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 173)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=173 len=102) from STA: EAP Response-unknown (52)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=1 id=174 len=38) from RADIUS server: EAP-Request-unknown (52)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 174)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=174 len=38) from STA: EAP Response-unknown (52)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: binding station to interface 'wlan1'
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=3 id=174 len=4) from RADIUS server: EAP Success
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 174)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: sending 1/4 msg of 4-Way Handshake
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: received EAPOL-Key frame (2/4 Pairwise)
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: sending 3/4 msg of 4-Way Handshake
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: received EAPOL-Key frame (4/4 Pairwise)
Fri Sep  1 19:51:38 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: pairwise key handshake completed (RSN)
Fri Sep  1 19:51:38 2017 daemon.notice hostapd: wlan1: AP-STA-CONNECTED f8:32:e4:0f:6c:c9
Fri Sep  1 19:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: authorizing port
Fri Sep  1 19:51:38 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: starting accounting session B37353698865B585
Fri Sep  1 19:51:38 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Fri Sep  1 19:51:38 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: authenticated
Fri Sep  1 19:51:39 2017 daemon.info dnsmasq-dhcp[3523]: DHCPREQUEST(br-lan) 192.168.1.97 f8:32:e4:0f:6c:c9 
Fri Sep  1 19:51:39 2017 daemon.info dnsmasq-dhcp[3523]: DHCPNAK(br-lan) 192.168.1.97 f8:32:e4:0f:6c:c9 wrong address
Fri Sep  1 19:51:40 2017 daemon.info dnsmasq-dhcp[3523]: DHCPDISCOVER(br-lan) f8:32:e4:0f:6c:c9 
Fri Sep  1 19:51:40 2017 daemon.info dnsmasq-dhcp[3523]: DHCPOFFER(br-lan) 192.168.1.182 f8:32:e4:0f:6c:c9 
Fri Sep  1 19:51:40 2017 daemon.info dnsmasq-dhcp[3523]: DHCPREQUEST(br-lan) 192.168.1.182 f8:32:e4:0f:6c:c9 
Fri Sep  1 19:51:40 2017 daemon.info dnsmasq-dhcp[3523]: DHCPACK(br-lan) 192.168.1.182 f8:32:e4:0f:6c:c9 android-f5a744f7ce6799ce

And at EXACLY 1 hour after (20:51:38) the client STOPS receiving packets from router

Fri Sep  1 20:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: event 5 notification
Fri Sep  1 20:51:38 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-STARTED f8:32:e4:0f:6c:c9
Fri Sep  1 20:51:38 2017 daemon.notice hostapd: wlan1: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Fri Sep  1 20:51:38 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 178)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=178 len=12) from STA: EAP Response-Identity (1)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: STA identity 'pimenta'
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received 94 bytes from RADIUS server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=1 id=179 len=36) from RADIUS server: EAP-Request-unknown (52)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 179)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=179 len=22) from STA: EAP Response-unknown (52)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received 160 bytes from RADIUS server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.04 sec
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=1 id=180 len=102) from RADIUS server: EAP-Request-unknown (52)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 180)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=180 len=102) from STA: EAP Response-unknown (52)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received 96 bytes from RADIUS server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.01 sec
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=1 id=181 len=38) from RADIUS server: EAP-Request-unknown (52)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 181)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: received EAP packet (code=2 id=181 len=38) from STA: EAP Response-unknown (52)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Sending RADIUS message to authentication server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received 169 bytes from RADIUS server
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: RADIUS Received RADIUS message
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.01 sec
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.11: binding station to interface 'wlan1'
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: old identity 'pimenta' updated with User-Name from Access-Accept 'pimenta'
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: decapsulated EAP packet (code=3 id=181 len=4) from RADIUS server: EAP Success
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: Sending EAP Packet (identifier 181)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: authorizing port
Fri Sep  1 20:51:39 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 RADIUS: starting accounting session B37353698865B585
Fri Sep  1 20:51:39 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 IEEE 802.1X: authenticated - EAP type: 52 (unknown)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: sending 1/4 msg of 4-Way Handshake
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: received EAPOL-Key frame (2/4 Pairwise)
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: sending 3/4 msg of 4-Way Handshake
Fri Sep  1 20:51:39 2017 daemon.debug hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: received EAPOL-Key frame (4/4 Pairwise)
Fri Sep  1 20:51:39 2017 daemon.info hostapd: wlan1: STA f8:32:e4:0f:6c:c9 WPA: pairwise key handshake completed (RSN)

Maybe this problem is related to hostapd, ou other software in LEDE, maybe I should report this problem...

yuhhaurlin commented 7 years ago

It looks like connection is still there, but no address assigned. Can you use static IP to do test and when the problem happen, please ping to router. BTW, you only run YouTube to let this problem happen? Please also help to check if stock firmware has the same problem. Thanks.

s-pimenta commented 7 years ago

No it doesn't need to be YouTube, can be anything...

I can try using static ip address, and also use stock firmware...

starcms commented 7 years ago

@yuhhaurlin, I honestly think the issue is with the full version of wpad (as opposed to wpad-mini), not with mwlwifi.

Problem only exists when using wpad with WPA2-EAP. Stock firmware doesn't support WPA2-EAP.

yuhhaurlin commented 7 years ago

@s-pimenta If stock firmware is all right, please help to check PSK. Thanks.

s-pimenta commented 7 years ago

I'm testing now with stock firmware

s-pimenta commented 7 years ago

It seems the problem is related with the type of authentication used... Using WPA2-PSK CCMP does solve the problem, both on stock firmware and DD-WRT and LEDE/OpenWRT.

But on DD-WRT the router locked up completely after some time, (no Wifi no Ethernet), and give up and switched to LEDE/OpenWRT...

After about 18 hours of uptime, using LEDE/OpenWRT (davidc502 build), the router just lockup completly... no Wifi (both LED's stayed ON) and no ethernet... so no way to see the logs after... I still leaved the router locked up by about 1 hour but it didn't reboot by itself...

I don't think that is happening the same problem as (https://github.com/kaloz/mwlwifi/issues/212) issue because when it happen just 2.4 GHz died (LED OFF) and ethernet and 5GHz Wifi went just fine...

I need to put a pen drive or a Raspberry Pi log server to see what's happening this time...

s-pimenta commented 7 years ago

Another think I noticed after the reboot the temperatures reported of both radios was more higher than usual, and they drop to normal temperatures (room temperature stayed the same)... I've never seen an temperature drop when the router stayed ON for several hours.

It looks like when the lockup happens the Wifi cards stay at some high load...

sensors sensors 1 sensors 2

BrainSlayer commented 7 years ago

the lockup is a wifi driver crash caused by a the wifi hw firmware as it sems. i have see this in several logs. but there is no solution until marvell finally is able to reproduce it and fixes it

BrainSlayer commented 7 years ago

it always starts with a unresponsible wifi driver firmware and ends with a nullpoint exception within the wifi driver example: [180243.609205] ieee80211 phy0: cmd 0x801d=MEMAddrAccess timed out [180243.615158] ieee80211 phy0: return code: 0x001d [180243.619795] ieee80211 phy0: timeout: 0x001d [180247.623199] ieee80211 phy0: cmd 0x801d=MEMAddrAccess timed out [180247.629148] ieee80211 phy0: return code: 0x001d [180247.633798] ieee80211 phy0: timeout: 0x001d [180251.639213] ieee80211 phy0: cmd 0x9125=BAStream timed out [180251.644756] ieee80211 phy0: return code: 0x1125 [180251.649392] ieee80211 phy0: timeout: 0x1125 [180251.653855] Unable to handle kernel NULL pointer dereference at virtual address 0000000c

BrainSlayer commented 7 years ago

but the only way to log this is using a serial adapter

yuhhaurlin commented 7 years ago

The driver does not support AES+TKIP. If AES only resolves your problem, I will close this one. Device totally locked won't be problem of host command timeout. For host command timeout, I need the way to reproduce it on LEDE image.

Chadster766 commented 7 years ago

I've implemented WPA2 Enterprise in a production environment with McDebain and so far mwlwifi 0606 have been very stable.