#21284: EA3500 (Audi Kirkwood) wifi unstable.
------------------------+---------------------------------------
Reporter: anonymous | Owner: developers
Type: defect | Status: new
Priority: normal | Milestone: Designated Driver (Trunk)
Component: kernel | Version: Trunk
Resolution: | Keywords:
------------------------+---------------------------------------
Comment (by lordgilman):
Ok, I built wpad with increased timeouts. I also brought down the
interval between GTK rekeys to make this easier to test. The rekey
success rate was pretty good but there were still a few nasty drops. I
managed to get this capture for one of them. The syslog with timestamps
is first, the hostapd debug log is second:
{{{
Sun Jul 10 06:00:12 2016 daemon.debug hostapd: wlan1: WPA rekeying GTK
Sun Jul 10 06:00:12 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
sending 1/2 msg of Group Key Handshake
Sun Jul 10 06:00:13 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
EAPOL-Key timeout
Sun Jul 10 06:00:13 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
sending 1/2 msg of Group Key Handshake
Sun Jul 10 06:00:15 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
EAPOL-Key timeout
Sun Jul 10 06:00:15 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
sending 1/2 msg of Group Key Handshake
Sun Jul 10 06:00:17 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
EAPOL-Key timeout
Sun Jul 10 06:00:17 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
sending 1/2 msg of Group Key Handshake
Sun Jul 10 06:00:19 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
EAPOL-Key timeout
Sun Jul 10 06:00:19 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
WPA_PTK: sm->Disconnect
Sun Jul 10 06:00:19 2016 daemon.debug hostapd: wlan1: STA (bad phone) WPA:
event 3 notification
Sun Jul 10 06:00:19 2016 daemon.debug hostapd: wlan1: STA (bad phone) IEEE
802.1X: unauthorizing port
Sun Jul 10 06:00:19 2016 daemon.debug hostapd: wlan1: STA (bad phone)
MLME: MLME-DEAUTHENTICATE.indication((bad phone), 2)
Sun Jul 10 06:00:19 2016 daemon.debug hostapd: wlan1: STA (bad phone)
MLME: MLME-DELETEKEYS.request((bad phone))
Sun Jul 10 06:00:19 2016 kern.debug kernel: [110316.263312] ieee80211
phy1: Deleted BA stream index 0
Sun Jul 10 06:00:19 2016 kern.debug kernel: [110316.263422] ieee80211
phy1: Remove stream for (bad phone) 0
Sun Jul 10 06:00:24 2016 daemon.info hostapd: wlan1: STA (bad phone) IEEE
802.11: deauthenticated due to local deauth request
wlan1: WPA rekeying GTK
WPA: group state machine entering state SETKEYS (VLAN-ID 0)
GTK - hexdump(len=16): [REMOVED]
WPA: (bad phone) WPA_PTK_GROUP entering state REKEYNEGOTIATING
wlan1: STA (bad phone) WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0
kde_len=24 keyidx=2 encr=1)
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 10
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 1)
wpa_group_setkeys: GKeyDoneStations=1
wlan1: STA (bad phone) WPA: EAPOL-Key timeout
WPA: (bad phone) WPA_PTK_GROUP entering state REKEYNEGOTIATING
wlan1: STA (bad phone) WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0
kde_len=24 keyidx=2 encr=1)
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 11
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 2)
wlan1: STA (bad phone) WPA: EAPOL-Key timeout
WPA: (bad phone) WPA_PTK_GROUP entering state REKEYNEGOTIATING
wlan1: STA (bad phone) WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0
kde_len=24 keyidx=2 encr=1)
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 12
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-67 fc=0x40
seq_ctrl=0x2c0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=68
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-67 fc=0x40
seq_ctrl=0x2d0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=175
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-68 fc=0x40
seq_ctrl=0x2e0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=42
nl80211: send_mlme - da= cc:95:d7:d9:3d:95 noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-67 fc=0x40
seq_ctrl=0x2f0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=149
nl80211: send_mlme - da= cc:95:d7:d9:3d:95 noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
wlan1: STA (bad phone) WPA: EAPOL-Key timeout
WPA: (bad phone) WPA_PTK_GROUP entering state REKEYNEGOTIATING
wlan1: STA (bad phone) WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0
kde_len=24 keyidx=2 encr=1)
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 13
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 4)
wlan1: STA (bad phone) WPA: EAPOL-Key timeout
WPA: (bad phone) WPA_PTK_GROUP entering state REKEYNEGOTIATING
WPA: (bad phone) WPA_PTK_GROUP entering state KEYERROR
WPA: group state machine entering state SETKEYSDONE (VLAN-ID 0)
wpa_driver_nl80211_set_key: ifindex=16 (wlan1) alg=3 addr=0x88608
key_idx=2 set_tx=1 seq_len=0 key_len=16
nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
broadcast key
wlan1: STA (bad phone) WPA: WPA_PTK: sm->Disconnect
WPA: (bad phone) WPA_PTK entering state DISCONNECT
wpa_sta_disconnect STA (bad phone)
hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA
(bad phone) reason 2
wlan1: ap_sta_disconnect addr (bad phone) reason=2
nl80211: send_mlme - da= (bad phone) noack=0 freq=0 no_cck=0 offchanok=0
wait_time=0 fc=0xc0 (WLAN_FC_STYPE_DEAUTH) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
wlan1: AP-STA-DISCONNECTED (bad phone)
wlan1: STA (bad phone) WPA: event 3 notification
wpa_driver_nl80211_set_key: ifindex=16 (wlan1) alg=0 addr=0xb6eda428
key_idx=0 set_tx=1 seq_len=0 key_len=0
addr=(bad phone)
wlan1: ap_sta_disconnect: reschedule ap_handle_timer timeout for (bad
phone) (5 seconds - AP_MAX_INACTIVITY_AFTER_DEAUTH)
WPA: (bad phone) WPA_PTK_GROUP entering state IDLE
WPA: (bad phone) WPA_PTK entering state DISCONNECTED
WPA: (bad phone) WPA_PTK entering state INITIALIZE
wpa_driver_nl80211_set_key: ifindex=16 (wlan1) alg=0 addr=0xb6eda428
key_idx=0 set_tx=1 seq_len=0 key_len=0
addr=(bad phone)
nl80211: Set STA flags - ifname=wlan1 addr=(bad phone) total_flags=0x2
flags_or=0x0 flags_and=0xfffffffe authorized=0
wlan1: STA (bad phone) IEEE 802.1X: unauthorizing port
nl80211: Drv Event 60 (NL80211_CMD_FRAME_TX_STATUS) received for wlan1
nl80211: Frame TX status event
wlan1: Event TX_STATUS (17) received
mgmt::deauth cb
STA (bad phone) acknowledged deauth
wlan1: Deauthentication callback for STA (bad phone)
wlan1: Removing STA (bad phone) from kernel driver
nl80211: sta_remove -> DEL_STATION wlan1 (bad phone) --> 0 (No error
information)
wlan1: STA (bad phone) MLME: MLME-DEAUTHENTICATE.indication((bad phone),
2)
wlan1: STA (bad phone) MLME: MLME-DELETEKEYS.request((bad phone))
wpa_driver_nl80211_set_key: ifindex=16 (wlan1) alg=0 addr=0xb6eda428
key_idx=0 set_tx=1 seq_len=0 key_len=0
addr=(bad phone)
wlan1: Event EAPOL_TX_STATUS (38) received
Ignore TX status for Data frame to STA (bad phone) that is not currently
associated
nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan1
nl80211: Delete station (bad phone)
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=(bad phone) freq=5180 ssi_signal=-44 fc=0x40
seq_ctrl=0x71e0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=120
nl80211: send_mlme - da= (bad phone) noack=0 freq=0 no_cck=0 offchanok=0
wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
wlan1: Event EAPOL_TX_STATUS (38) received
Ignore TX status for Data frame to STA (bad phone) that is not currently
associated
nl80211: Drv Event 60 (NL80211_CMD_FRAME_TX_STATUS) received for wlan1
nl80211: Frame TX status event
wlan1: Event TX_STATUS (17) received
wlan1: Event EAPOL_TX_STATUS (38) received
Ignore TX status for Data frame to STA (bad phone) that is not currently
associated
wlan1: Event EAPOL_TX_STATUS (38) received
Ignore TX status for Data frame to STA (bad phone) that is not currently
associated
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=(bad phone) freq=5180 ssi_signal=-43 fc=0x40
seq_ctrl=0x7350 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=106
nl80211: send_mlme - da= (bad phone) noack=1 freq=0 no_cck=0 offchanok=0
wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=(bad phone) freq=5180 ssi_signal=-43 fc=0x40
seq_ctrl=0x7360 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=106
nl80211: send_mlme - da= (bad phone) noack=1 freq=0 no_cck=0 offchanok=0
wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=e0:66:78:80:e1:4a freq=5180 ssi_signal=-74 fc=0x40
seq_ctrl=0xc0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=131
nl80211: send_mlme - da= e0:66:78:80:e1:4a noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
wlan1: ap_handle_timer: (bad phone) flags=0x8a00 timeout_next=3
wlan1: STA (bad phone) IEEE 802.11: deauthenticated due to local deauth
request
nl80211: sta_remove -> DEL_STATION wlan1 (bad phone) --> -2 (No such file
or directory)
hostapd_ht_operation_update current operation mode=0x4
hostapd_ht_operation_update new operation mode=0x0 changes=1
nl80211: Set beacon (beacon_set=1)
nl80211: Beacon head - hexdump(len=65): 80 00 00 00 ff ff ff ff ff ff 94
10 3e 8f d2 db 94 10 3e 8f d2 db 00 00 00 00 00 00 00 00 00 00 64 00 31 00
00 0e 67 69 6c 6d 61 6e 20 6f 70 65 6e 77 72 74 01 08 8c 12 98 24 b0 48 60
6c 03 01 24
nl80211: Beacon tail - hexdump(len=118): 07 06 30 30 20 24 04 14 30 14 01
00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 0c 00 2d 1a ec 0b 03 ff
ff ff 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 3d 16 24
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7f 08 00 00
00 00 00 00 00 40 dd 18 00 50 f2 02 01 01 00 00 03 a4 00 00 27 a4 00 00 42
43 5e 00 62 32 2f 00
nl80211: ifindex=16
nl80211: beacon_int=100
nl80211: dtim_period=2
nl80211: ssid - hexdump_ascii(len=14):
67 69 6c 6d 61 6e 20 6f 70 65 6e 77 72 74 gilman openwrt
* beacon_int=100
nl80211: hidden SSID not in use
nl80211: privacy=1
nl80211: auth_algs=0x1
nl80211: wpa_version=0x2
nl80211: key_mgmt_suites=0x2
nl80211: pairwise_ciphers=0x10
nl80211: group_cipher=0x10
nl80211: SMPS mode - off
nl80211: beacon_ies - hexdump(len=10): 7f 08 00 00 00 00 00 00 00 40
nl80211: proberesp_ies - hexdump(len=10): 7f 08 00 00 00 00 00 00 00 40
nl80211: assocresp_ies - hexdump(len=10): 7f 08 00 00 00 00 00 00 00 40
ap_free_sta: cancel ap_handle_timer for (bad phone)
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-67 fc=0x40
seq_ctrl=0x2c0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=68
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-68 fc=0x40
seq_ctrl=0x2d0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=175
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-68 fc=0x40
seq_ctrl=0x2e0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=42
nl80211: send_mlme - da= cc:95:d7:d9:3d:95 noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-68 fc=0x40
seq_ctrl=0x2f0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=149
nl80211: send_mlme - da= cc:95:d7:d9:3d:95 noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
wlan1: WPA rekeying GTK
WPA: group state machine entering state SETKEYS (VLAN-ID 0)
GTK - hexdump(len=16): [REMOVED]
wpa_group_setkeys: GKeyDoneStations=0
WPA: group state machine entering state SETKEYSDONE (VLAN-ID 0)
wpa_driver_nl80211_set_key: ifindex=16 (wlan1) alg=3 addr=0x88608
key_idx=1 set_tx=1 seq_len=0 key_len=16
nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
broadcast key
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=(bad phone) freq=5180 ssi_signal=-62 fc=0x40
seq_ctrl=0x7730 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=106
nl80211: send_mlme - da= (bad phone) noack=1 freq=0 no_cck=0 offchanok=0
wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=(bad phone) freq=5180 ssi_signal=-62 fc=0x40
seq_ctrl=0x7740 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=106
nl80211: send_mlme - da= (bad phone) noack=1 freq=0 no_cck=0 offchanok=0
wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-67 fc=0x40
seq_ctrl=0x2c0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=68
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-68 fc=0x40
seq_ctrl=0x2d0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=175
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-68 fc=0x40
seq_ctrl=0x2e0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=42
nl80211: send_mlme - da= cc:95:d7:d9:3d:95 noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for wlan1
nl80211: RX frame sa=cc:95:d7:d9:3d:95 freq=5180 ssi_signal=-67 fc=0x40
seq_ctrl=0x2f0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=149
nl80211: send_mlme - da= cc:95:d7:d9:3d:95 noack=1 freq=0 no_cck=0
offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
nl80211: send_mlme -> send_frame
nl80211: send_frame - Use bss->freq=5180
nl80211: send_frame -> send_frame_cmd
nl80211: Drop oldest pending send action cookie 0x0
}}}
Do you see the four "Event EAPOL_TX_STATUS (38) received" lines that come
in after the sm->Disconnect log line? I am wondering if that's the four
EAPOL responses coming in super late - in this case 7 or 8 seconds after
they were initially sent! I'm going to try rebuilding with
eapol_key_timeout_subseq set to 10 seconds and everything else left on
default.
--
Ticket URL: <https://dev.openwrt.org/ticket/21284#comment:34>
OpenWrt <http://openwrt.org>
Opensource Wireless Router Technology
_______________________________________________
openwrt-tickets mailing list
openwrt-tickets@lists.openwrt.org
https://lists.openwrt.org/cgi-bin/mailman/listinfo/openwrt-tickets
