[RFC PATCH] Increase GTK/PTK rekey retries

Tue Dec 20 00:15:14 PST 2016

Hi

I forgot to add the log which shows the error case:

Hostapd tries to negotiate a new GTK 4 times with timeouts 500ms, 1s, 1s, 1s
before giving up and deauthenticating the station. Log shows that the EAPOL
messages are all acked only after 4s when the deauthentication already finished.

(log filtered for specific MAC address and 'EAPOL')
Dec 15 17:09:12 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state REKEYNEGOTIATING
Dec 15 17:09:12 192.168.19.225 hostapd: WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Dec 15 17:09:12 192.168.19.225 hostapd: Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
Dec 15 17:09:12 192.168.19.225 hostapd: WPA: Use EAPOL-Key timeout of 500 ms (retry counter 1)
Dec 15 17:09:13 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state REKEYNEGOTIATING
Dec 15 17:09:13 192.168.19.225 hostapd: WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Dec 15 17:09:13 192.168.19.225 hostapd: Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
Dec 15 17:09:13 192.168.19.225 hostapd: WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 2)
Dec 15 17:09:14 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state REKEYNEGOTIATING
Dec 15 17:09:14 192.168.19.225 hostapd: WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Dec 15 17:09:14 192.168.19.225 hostapd: Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
Dec 15 17:09:14 192.168.19.225 hostapd: WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 3)
Dec 15 17:09:15 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state REKEYNEGOTIATING
Dec 15 17:09:15 192.168.19.225 hostapd: WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Dec 15 17:09:15 192.168.19.225 hostapd: Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
Dec 15 17:09:15 192.168.19.225 hostapd: WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 4)
Dec 15 17:09:16 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state REKEYNEGOTIATING
Dec 15 17:09:16 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state KEYERROR
Dec 15 17:09:16 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK entering state DISCONNECT
Dec 15 17:09:16 192.168.19.225 hostapd: wpa_sta_disconnect STA e8:50:8b:xx:xx:xx
Dec 15 17:09:16 192.168.19.225 hostapd: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA e8:50:8b:xx:xx:xx reason 2
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: send_mlme - da= e8:50:8b:xx:xx:xx noack=0 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0xc0 (WLAN_FC_STYPE_DEAUTH) nlmode=3
Dec 15 17:09:16 192.168.19.225 hostapd: wlan1: AP-STA-DISCONNECTED e8:50:8b:xx:xx:xx
Dec 15 17:09:16 192.168.19.225 hostapd:    addr=e8:50:8b:xx:xx:xx
Dec 15 17:09:16 192.168.19.225 hostapd: ap_sta_disconnect: reschedule ap_handle_timer timeout for e8:50:8b:xx:xx:xx (5 seconds - AP_MAX_INACTIVITY_AFTER_DEAUTH)
Dec 15 17:09:16 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK_GROUP entering state IDLE
Dec 15 17:09:16 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK entering state DISCONNECTED
Dec 15 17:09:16 192.168.19.225 hostapd: WPA: e8:50:8b:xx:xx:xx WPA_PTK entering state INITIALIZE
Dec 15 17:09:16 192.168.19.225 hostapd:    addr=e8:50:8b:xx:xx:xx
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: Set STA flags - ifname=wlan1-2 addr=e8:50:8b:xx:xx:xx total_flags=0x6 flags_or=0x0 flags_and=0xfffffffe authorized=0
Dec 15 17:09:16 192.168.19.225 hostapd: wlan1: Event EAPOL_TX_STATUS (38) received
Dec 15 17:09:16 192.168.19.225 hostapd: Ignore TX status for Data frame to STA e8:50:8b:xx:xx:xx that is not currently associated
Dec 15 17:09:16 192.168.19.225 hostapd: STA e8:50:8b:xx:xx:xx acknowledged deauth
Dec 15 17:09:16 192.168.19.225 hostapd: Removing STA e8:50:8b:xx:xx:xx from kernel driver
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: sta_remove -> DEL_STATION wlan1-2 e8:50:8b:xx:xx:xx --> 0 (Success)
Dec 15 17:09:16 192.168.19.225 hostapd:    addr=e8:50:8b:xx:xx:xx
Dec 15 17:09:16 192.168.19.225 hostapd: wlan1: Event EAPOL_TX_STATUS (38) received
Dec 15 17:09:16 192.168.19.225 hostapd: Ignore TX status for Data frame to STA e8:50:8b:xx:xx:xx that is not currently associated
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: Delete station e8:50:8b:xx:xx:xx
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=2412 ssi_signal=-48 fc=0x40 seq_ctrl=0x83f0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=142
Dec 15 17:09:16 192.168.19.225 hostapd: wlan1: Event EAPOL_TX_STATUS (38) received
Dec 15 17:09:16 192.168.19.225 hostapd: Ignore TX status for Data frame to STA e8:50:8b:xx:xx:xx that is not currently associated
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=2412 ssi_signal=-48 fc=0x40 seq_ctrl=0x83f0 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=142
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: send_mlme - da= e8:50:8b:xx:xx:xx noack=0 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=5180 ssi_signal=-44 fc=0x40 seq_ctrl=0x8410 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=133
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=5180 ssi_signal=-44 fc=0x40 seq_ctrl=0x8410 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=133
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=5180 ssi_signal=-44 fc=0x40 seq_ctrl=0x8410 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=133
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: send_mlme - da= e8:50:8b:xx:xx:xx noack=0 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=2412 ssi_signal=-47 fc=0x40 seq_ctrl=0x8400 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=142
Dec 15 17:09:16 192.168.19.225 hostapd: wlan1: Event EAPOL_TX_STATUS (38) received
Dec 15 17:09:16 192.168.19.225 hostapd: Ignore TX status for Data frame to STA e8:50:8b:xx:xx:xx that is not currently associated
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=2412 ssi_signal=-47 fc=0x40 seq_ctrl=0x8400 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=142
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=2412 ssi_signal=-47 fc=0x40 seq_ctrl=0x8400 stype=4 (WLAN_FC_STYPE_PROBE_REQ) len=142
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: send_mlme - da= e8:50:8b:xx:xx:xx noack=0 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: RX frame sa=e8:50:8b:xx:xx:xx freq=5180 ssi_signal=-44 fc=0xb0 seq_ctrl=0x8430 stype=11 (WLAN_FC_STYPE_AUTH) len=41
Dec 15 17:09:16 192.168.19.225 hostapd: authentication: STA=e8:50:8b:xx:xx:xx auth_alg=0 auth_transaction=1 status_code=0 wep=0 seq_ctrl=0x8430
Dec 15 17:09:16 192.168.19.225 hostapd: ap_sta_add: register ap_handle_timer timeout for e8:50:8b:xx:xx:xx (300 seconds - ap_max_inactivity)
Dec 15 17:09:16 192.168.19.225 hostapd: authentication reply: STA=e8:50:8b:xx:xx:xx auth_alg=0 auth_transaction=2 resp=0 (IE len=0)
Dec 15 17:09:16 192.168.19.225 hostapd: nl80211: send_mlme - da= e8:50:8b:xx:xx:xx noack=0 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0xb0 (WLAN_FC_STYPE_AUTH) nlmode=3
Dec 15 17:09:16 192.168.19.225 hostapd: wlan0-2: STA e8:50:8b:xx:xx:xx IEEE 802.11: authenticated

Günther

> -----Original Message-----
> From: Hostap [mailto:hostap-bounces at lists.infradead.org] On Behalf Of
> Günther Kelleter
> Sent: Monday, December 19, 2016 5:06 PM
> To: hostap at lists.infradead.org
> Subject: [RFC PATCH] Increase GTK/PTK rekey retries
> 
> We are experiencing frequent deauthentication of Android stations due to
> GTK rekey failures: EAPOL frames are not answered during the total timeout
> peroid of 3.5 s. Increase retries to cover a bigger timeout period.
> 
> Signed-off-by: Günther Kelleter <guenther.kelleter at devolo.de>
> ---
>  src/ap/wpa_auth.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> There seems to be a common problem with Android devices getting
> deauthenticated
> frequently due to GTK rekey timeouts
> (https://code.google.com/p/android/issues/detail?id=196035#c56)
> This patch fixes it by increasing the total timeout period.
> 
> IMHO a proper fix for this issue would be to implement retransmit timeouts
> as
> mandated by 802.11-2012 Ch. 11.6.7.4:
> "The retransmit timeout value shall be 100 ms for the first timeout, half the
> listen interval for the second timeout, and the listen interval for subsequent
> timeouts. If there is no listen interval or the listen interval is zero, then
> 100 ms shall be used for all timeout values."
> 
> But 802.11 doesn't give any hints about the number of retries in
> dot11RSNAConfigGroupUpdateCount.
> 
> In our test case with Galaxy S6 the station announces a listen interval of
> 10 beacon periods corresponding in 1.024 seconds. But it remains in power
> save mode for about 5 seconds.
> 
> Isn't that a bug in Android which violates 802.11-2012 Ch. 10.2.1.8.a?
> "The STA shall wake up early enough to be able to receive the first Beacon
> frame scheduled for transmission at the time corresponding to the last TBTT
> plus the ListenInterval."
> 
> This Android bug would still require dot11RSNAConfigGroupUpdateCount to
> be at
> least 6 for successful GTK rekeying.
> 
> Obviously the same applies to PTK rekeying, where 802.11 mandates the
> same
> interval specification.
> 
> Is there a reason that hostapd does not implement retransmit timeouts as
> mandated by 802.11?
> 
> 
> diff --git a/src/ap/wpa_auth.c b/src/ap/wpa_auth.c
> index 43e3558..ba1b58d 100644
> --- a/src/ap/wpa_auth.c
> +++ b/src/ap/wpa_auth.c
> @@ -60,8 +60,8 @@ static void wpa_group_put(struct wpa_authenticator
> *wpa_auth,
>  			  struct wpa_group *group);
>  static u8 * ieee80211w_kde_add(struct wpa_state_machine *sm, u8 *pos);
> 
> -static const u32 dot11RSNAConfigGroupUpdateCount = 4;
> -static const u32 dot11RSNAConfigPairwiseUpdateCount = 4;
> +static const u32 dot11RSNAConfigGroupUpdateCount = 8;
> +static const u32 dot11RSNAConfigPairwiseUpdateCount = 8;
>  static const u32 eapol_key_timeout_first = 100; /* ms */
>  static const u32 eapol_key_timeout_subseq = 1000; /* ms */
>  static const u32 eapol_key_timeout_first_group = 500; /* ms */
> --
> 2.10.0.100.gddd73ec
> 
> 
> _______________________________________________
> Hostap mailing list
> Hostap at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/hostap