[PATCH] mac80211: start auth/assoc timeout on frame status

[PATCH] mac80211: start auth/assoc timeout on frame status

[Johannes Berg]

From: Johannes Berg <johannes.berg@intel.com>

When sending authentication/association frames they
might take a bit of time to go out because we may
have to synchronise with the AP, in particular in
the case where it's really a P2P GO. In this case
the 200ms fixed timeout could potentially be too
short if the beacon interval is relatively large.

For drivers that report TX status we can do better.
Instead of starting the timeout directly, start it
only when the frame status arrives. Since then the
frame was out on the air, we can wait shorter (the
typical response time is supposed to be 30ms, wait
100ms.) Also, if the frame failed to be transmitted
try again right away instead of waiting.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
 include/net/mac80211.h     |  5 ++-
 net/mac80211/ibss.c        |  4 +--
 net/mac80211/ieee80211_i.h | 11 ++++--
 net/mac80211/mlme.c        | 85 +++++++++++++++++++++++++++++++++++++++-------
 net/mac80211/scan.c        |  3 +-
 net/mac80211/status.c      | 12 ++++---
 net/mac80211/util.c        | 12 +++----
 7 files changed, 103 insertions(+), 29 deletions(-)

diff --git a/include/net/mac80211.h b/include/net/mac80211.h
index 398b6ca..164fd4b 100644
--- a/include/net/mac80211.h
+++ b/include/net/mac80211.h
@@ -408,6 +408,9 @@ struct ieee80211_bss_conf {
  * @IEEE80211_TX_INTFL_RETRANSMISSION: This frame is being retransmitted
  *	after TX status because the destination was asleep, it must not
  *	be modified again (no seqno assignment, crypto, etc.)
+ * @IEEE80211_TX_INTFL_MLME_CONN_TX: This frame was transmitted by the MLME
+ *	code for connection establishment, this indicates that its status
+ *	should kick the MLME state machine.
  * @IEEE80211_TX_INTFL_NL80211_FRAME_TX: Frame was requested through nl80211
  *	MLME command (internal to mac80211 to figure out whether to send TX
  *	status to user space)
@@ -459,7 +462,7 @@ enum mac80211_tx_control_flags {
 	IEEE80211_TX_CTL_NO_PS_BUFFER		= BIT(17),
 	IEEE80211_TX_CTL_MORE_FRAMES		= BIT(18),
 	IEEE80211_TX_INTFL_RETRANSMISSION	= BIT(19),
-	/* hole at 20, use later */
+	IEEE80211_TX_INTFL_MLME_CONN_TX		= BIT(20),
 	IEEE80211_TX_INTFL_NL80211_FRAME_TX	= BIT(21),
 	IEEE80211_TX_CTL_LDPC			= BIT(22),
 	IEEE80211_TX_CTL_STBC			= BIT(23) | BIT(24),
diff --git a/net/mac80211/ibss.c b/net/mac80211/ibss.c
index b4b866f..a54c824 100644
--- a/net/mac80211/ibss.c
+++ b/net/mac80211/ibss.c
@@ -302,7 +302,7 @@ static struct sta_info *ieee80211_ibss_finish_sta(struct sta_info *sta,
 			 "TX Auth SA=%pM DA=%pM BSSID=%pM (auth_transaction=1)\n",
 			 sdata->vif.addr, addr, sdata->u.ibss.bssid);
 		ieee80211_send_auth(sdata, 1, WLAN_AUTH_OPEN, 0, NULL, 0,
-				    addr, sdata->u.ibss.bssid, NULL, 0, 0);
+				    addr, sdata->u.ibss.bssid, NULL, 0, 0, 0);
 	}
 	return sta;
 }
@@ -422,7 +422,7 @@ static void ieee80211_rx_mgmt_auth_ibss(struct ieee80211_sub_if_data *sdata,
 	 * has actually implemented this.
 	 */
 	ieee80211_send_auth(sdata, 2, WLAN_AUTH_OPEN, 0, NULL, 0,
-			    mgmt->sa, sdata->u.ibss.bssid, NULL, 0, 0);
+			    mgmt->sa, sdata->u.ibss.bssid, NULL, 0, 0, 0);
 }
 
 static void ieee80211_rx_bss_info(struct ieee80211_sub_if_data *sdata,
diff --git a/net/mac80211/ieee80211_i.h b/net/mac80211/ieee80211_i.h
index e4ee168..c9c66de 100644
--- a/net/mac80211/ieee80211_i.h
+++ b/net/mac80211/ieee80211_i.h
@@ -415,6 +415,10 @@ struct ieee80211_if_managed {
 	bool beacon_crc_valid;
 	u32 beacon_crc;
 
+	bool status_acked;
+	bool status_received;
+	__le16 status_fc;
+
 	enum {
 		IEEE80211_MFP_DISABLED,
 		IEEE80211_MFP_OPTIONAL,
@@ -1284,6 +1288,8 @@ void ieee80211_sta_rx_queued_mgmt(struct ieee80211_sub_if_data *sdata,
 void ieee80211_sta_reset_beacon_monitor(struct ieee80211_sub_if_data *sdata);
 void ieee80211_sta_reset_conn_monitor(struct ieee80211_sub_if_data *sdata);
 void ieee80211_mgd_stop(struct ieee80211_sub_if_data *sdata);
+void ieee80211_mgd_conn_tx_status(struct ieee80211_sub_if_data *sdata,
+				  __le16 fc, bool acked);
 
 /* IBSS code */
 void ieee80211_ibss_notify_scan_completed(struct ieee80211_local *local);
@@ -1544,7 +1550,8 @@ static inline void ieee80211_add_pending_skbs(struct ieee80211_local *local,
 void ieee80211_send_auth(struct ieee80211_sub_if_data *sdata,
 			 u16 transaction, u16 auth_alg, u16 status,
 			 u8 *extra, size_t extra_len, const u8 *bssid,
-			 const u8 *da, const u8 *key, u8 key_len, u8 key_idx);
+			 const u8 *da, const u8 *key, u8 key_len, u8 key_idx,
+			 u32 tx_flags);
 void ieee80211_send_deauth_disassoc(struct ieee80211_sub_if_data *sdata,
 				    const u8 *bssid, u16 stype, u16 reason,
 				    bool send_frame, u8 *frame_buf);
@@ -1561,7 +1568,7 @@ struct sk_buff *ieee80211_build_probe_req(struct ieee80211_sub_if_data *sdata,
 void ieee80211_send_probe_req(struct ieee80211_sub_if_data *sdata, u8 *dst,
 			      const u8 *ssid, size_t ssid_len,
 			      const u8 *ie, size_t ie_len,
-			      u32 ratemask, bool directed, bool no_cck,
+			      u32 ratemask, bool directed, u32 tx_flags,
 			      struct ieee80211_channel *channel, bool scan);
 
 void ieee80211_sta_def_wmm_params(struct ieee80211_sub_if_data *sdata,
diff --git a/net/mac80211/mlme.c b/net/mac80211/mlme.c
index a5dba67..4ff52d0 100644
--- a/net/mac80211/mlme.c
+++ b/net/mac80211/mlme.c
@@ -30,11 +30,13 @@
 #include "rate.h"
 #include "led.h"
 
-#define IEEE80211_AUTH_TIMEOUT (HZ / 5)
-#define IEEE80211_AUTH_MAX_TRIES 3
-#define IEEE80211_AUTH_WAIT_ASSOC (HZ * 5)
-#define IEEE80211_ASSOC_TIMEOUT (HZ / 5)
-#define IEEE80211_ASSOC_MAX_TRIES 3
+#define IEEE80211_AUTH_TIMEOUT		(HZ / 5)
+#define IEEE80211_AUTH_TIMEOUT_SHORT	(HZ / 10)
+#define IEEE80211_AUTH_MAX_TRIES	3
+#define IEEE80211_AUTH_WAIT_ASSOC	(HZ * 5)
+#define IEEE80211_ASSOC_TIMEOUT		(HZ / 5)
+#define IEEE80211_ASSOC_TIMEOUT_SHORT	(HZ / 10)
+#define IEEE80211_ASSOC_MAX_TRIES	3
 
 static int max_nullfunc_tries = 2;
 module_param(max_nullfunc_tries, int, 0644);
@@ -644,6 +646,9 @@ static void ieee80211_send_assoc(struct ieee80211_sub_if_data *sdata)
 	drv_mgd_prepare_tx(local, sdata);
 
 	IEEE80211_SKB_CB(skb)->flags |= IEEE80211_TX_INTFL_DONT_ENCRYPT;
+	if (local->hw.flags & IEEE80211_HW_REPORTS_TX_ACK_STATUS)
+		IEEE80211_SKB_CB(skb)->flags |= IEEE80211_TX_CTL_REQ_TX_STATUS |
+						IEEE80211_TX_INTFL_MLME_CONN_TX;
 	ieee80211_tx_skb(sdata, skb);
 }
 
@@ -1707,7 +1712,7 @@ static void ieee80211_mgd_probe_ap_send(struct ieee80211_sub_if_data *sdata)
 			ssid_len = ssid[1];
 
 		ieee80211_send_probe_req(sdata, dst, ssid + 2, ssid_len, NULL,
-					 0, (u32) -1, true, false,
+					 0, (u32) -1, true, 0,
 					 ifmgd->associated->channel, false);
 		rcu_read_unlock();
 	}
@@ -1937,9 +1942,11 @@ static void ieee80211_destroy_auth_data(struct ieee80211_sub_if_data *sdata,
 static void ieee80211_auth_challenge(struct ieee80211_sub_if_data *sdata,
 				     struct ieee80211_mgmt *mgmt, size_t len)
 {
+	struct ieee80211_local *local = sdata->local;
 	struct ieee80211_mgd_auth_data *auth_data = sdata->u.mgd.auth_data;
 	u8 *pos;
 	struct ieee802_11_elems elems;
+	u32 tx_flags = 0;
 
 	pos = mgmt->u.auth.variable;
 	ieee802_11_parse_elems(pos, len - (pos - (u8 *) mgmt), &elems);
@@ -1947,11 +1954,14 @@ static void ieee80211_auth_challenge(struct ieee80211_sub_if_data *sdata,
 		return;
 	auth_data->expected_transaction = 4;
 	drv_mgd_prepare_tx(sdata->local, sdata);
+	if (local->hw.flags & IEEE80211_HW_REPORTS_TX_ACK_STATUS)
+		tx_flags = IEEE80211_TX_CTL_REQ_TX_STATUS |
+			   IEEE80211_TX_INTFL_MLME_CONN_TX;
 	ieee80211_send_auth(sdata, 3, auth_data->algorithm, 0,
 			    elems.challenge - 2, elems.challenge_len + 2,
 			    auth_data->bss->bssid, auth_data->bss->bssid,
 			    auth_data->key, auth_data->key_len,
-			    auth_data->key_idx);
+			    auth_data->key_idx, tx_flags);
 }
 
 static enum rx_mgmt_action __must_check
@@ -2869,12 +2879,17 @@ static int ieee80211_probe_auth(struct ieee80211_sub_if_data *sdata)
 	struct ieee80211_local *local = sdata->local;
 	struct ieee80211_if_managed *ifmgd = &sdata->u.mgd;
 	struct ieee80211_mgd_auth_data *auth_data = ifmgd->auth_data;
+	u32 tx_flags = 0;
 
 	lockdep_assert_held(&ifmgd->mtx);
 
 	if (WARN_ON_ONCE(!auth_data))
 		return -EINVAL;
 
+	if (local->hw.flags & IEEE80211_HW_REPORTS_TX_ACK_STATUS)
+		tx_flags = IEEE80211_TX_CTL_REQ_TX_STATUS |
+			   IEEE80211_TX_INTFL_MLME_CONN_TX;
+
 	auth_data->tries++;
 
 	if (auth_data->tries > IEEE80211_AUTH_MAX_TRIES) {
@@ -2911,7 +2926,8 @@ static int ieee80211_probe_auth(struct ieee80211_sub_if_data *sdata)
 		ieee80211_send_auth(sdata, trans, auth_data->algorithm, status,
 				    auth_data->data, auth_data->data_len,
 				    auth_data->bss->bssid,
-				    auth_data->bss->bssid, NULL, 0, 0);
+				    auth_data->bss->bssid, NULL, 0, 0,
+				    tx_flags);
 	} else {
 		const u8 *ssidie;
 
@@ -2930,13 +2946,15 @@ static int ieee80211_probe_auth(struct ieee80211_sub_if_data *sdata)
 		 * will not answer to direct packet in unassociated state.
 		 */
 		ieee80211_send_probe_req(sdata, NULL, ssidie + 2, ssidie[1],
-					 NULL, 0, (u32) -1, true, false,
+					 NULL, 0, (u32) -1, true, tx_flags,
 					 auth_data->bss->channel, false);
 		rcu_read_unlock();
 	}
 
-	auth_data->timeout = jiffies + IEEE80211_AUTH_TIMEOUT;
-	run_again(ifmgd, auth_data->timeout);
+	if (!(local->hw.flags & IEEE80211_HW_REPORTS_TX_ACK_STATUS)) {
+		auth_data->timeout = jiffies + IEEE80211_AUTH_TIMEOUT;
+		run_again(ifmgd, auth_data->timeout);
+	}
 
 	return 0;
 }
@@ -2967,12 +2985,26 @@ static int ieee80211_do_assoc(struct ieee80211_sub_if_data *sdata)
 		   IEEE80211_ASSOC_MAX_TRIES);
 	ieee80211_send_assoc(sdata);
 
-	assoc_data->timeout = jiffies + IEEE80211_ASSOC_TIMEOUT;
-	run_again(&sdata->u.mgd, assoc_data->timeout);
+	if (!(local->hw.flags & IEEE80211_HW_REPORTS_TX_ACK_STATUS)) {
+		assoc_data->timeout = jiffies + IEEE80211_ASSOC_TIMEOUT;
+		run_again(&sdata->u.mgd, assoc_data->timeout);
+	}
 
 	return 0;
 }
 
+void ieee80211_mgd_conn_tx_status(struct ieee80211_sub_if_data *sdata,
+				  __le16 fc, bool acked)
+{
+	struct ieee80211_local *local = sdata->local;
+
+	sdata->u.mgd.status_fc = fc;
+	sdata->u.mgd.status_acked = acked;
+	sdata->u.mgd.status_received = true;
+
+	ieee80211_queue_work(&local->hw, &sdata->work);
+}
+
 void ieee80211_sta_work(struct ieee80211_sub_if_data *sdata)
 {
 	struct ieee80211_local *local = sdata->local;
@@ -2980,6 +3012,33 @@ void ieee80211_sta_work(struct ieee80211_sub_if_data *sdata)
 
 	mutex_lock(&ifmgd->mtx);
 
+	if (ifmgd->status_received) {
+		__le16 fc = ifmgd->status_fc;
+		bool status_acked = ifmgd->status_acked;
+
+		ifmgd->status_received = false;
+		if (ifmgd->auth_data &&
+		    (ieee80211_is_probe_req(fc) || ieee80211_is_auth(fc))) {
+			if (status_acked) {
+				ifmgd->auth_data->timeout =
+					jiffies + IEEE80211_AUTH_TIMEOUT_SHORT;
+				run_again(ifmgd, ifmgd->auth_data->timeout);
+			} else {
+				ifmgd->auth_data->timeout = jiffies - 1;
+			}
+		} else if (ifmgd->assoc_data &&
+			   (ieee80211_is_assoc_req(fc) ||
+			    ieee80211_is_reassoc_req(fc))) {
+			if (status_acked) {
+				ifmgd->assoc_data->timeout =
+					jiffies + IEEE80211_ASSOC_TIMEOUT_SHORT;
+				run_again(ifmgd, ifmgd->assoc_data->timeout);
+			} else {
+				ifmgd->assoc_data->timeout = jiffies - 1;
+			}
+		}
+	}
+
 	if (ifmgd->auth_data &&
 	    time_after(jiffies, ifmgd->auth_data->timeout)) {
 		if (ifmgd->auth_data->done) {
diff --git a/net/mac80211/scan.c b/net/mac80211/scan.c
index 061595a..85d0e5e 100644
--- a/net/mac80211/scan.c
+++ b/net/mac80211/scan.c
@@ -389,7 +389,8 @@ static void ieee80211_scan_state_send_probe(struct ieee80211_local *local,
 			local->scan_req->ssids[i].ssid_len,
 			local->scan_req->ie, local->scan_req->ie_len,
 			local->scan_req->rates[band], false,
-			local->scan_req->no_cck,
+			local->scan_req->no_cck ?
+				IEEE80211_TX_CTL_NO_CCK_RATE : 0,
 			local->hw.conf.channel, true);
 
 	/*
diff --git a/net/mac80211/status.c b/net/mac80211/status.c
index ab50285..d041de0 100644
--- a/net/mac80211/status.c
+++ b/net/mac80211/status.c
@@ -335,7 +335,8 @@ static void ieee80211_report_used_skb(struct ieee80211_local *local,
 	if (dropped)
 		acked = false;
 
-	if (info->flags & IEEE80211_TX_INTFL_NL80211_FRAME_TX) {
+	if (info->flags & (IEEE80211_TX_INTFL_NL80211_FRAME_TX |
+			   IEEE80211_TX_INTFL_MLME_CONN_TX)) {
 		struct ieee80211_sub_if_data *sdata = NULL;
 		struct ieee80211_sub_if_data *iter_sdata;
 		u64 cookie = (unsigned long)skb;
@@ -357,10 +358,13 @@ static void ieee80211_report_used_skb(struct ieee80211_local *local,
 			sdata = rcu_dereference(local->p2p_sdata);
 		}
 
-		if (!sdata)
+		if (!sdata) {
 			skb->dev = NULL;
-		else if (ieee80211_is_nullfunc(hdr->frame_control) ||
-			 ieee80211_is_qos_nullfunc(hdr->frame_control)) {
+		} else if (info->flags & IEEE80211_TX_INTFL_MLME_CONN_TX) {
+			ieee80211_mgd_conn_tx_status(sdata, hdr->frame_control,
+						     acked);
+		} else if (ieee80211_is_nullfunc(hdr->frame_control) ||
+			   ieee80211_is_qos_nullfunc(hdr->frame_control)) {
 			cfg80211_probe_status(sdata->dev, hdr->addr1,
 					      cookie, acked, GFP_ATOMIC);
 		} else {
diff --git a/net/mac80211/util.c b/net/mac80211/util.c
index 1c74512..139ad9b 100644
--- a/net/mac80211/util.c
+++ b/net/mac80211/util.c
@@ -1030,7 +1030,8 @@ u32 ieee80211_mandatory_rates(struct ieee80211_local *local,
 void ieee80211_send_auth(struct ieee80211_sub_if_data *sdata,
 			 u16 transaction, u16 auth_alg, u16 status,
 			 u8 *extra, size_t extra_len, const u8 *da,
-			 const u8 *bssid, const u8 *key, u8 key_len, u8 key_idx)
+			 const u8 *bssid, const u8 *key, u8 key_len, u8 key_idx,
+			 u32 tx_flags)
 {
 	struct ieee80211_local *local = sdata->local;
 	struct sk_buff *skb;
@@ -1063,7 +1064,8 @@ void ieee80211_send_auth(struct ieee80211_sub_if_data *sdata,
 		WARN_ON(err);
 	}
 
-	IEEE80211_SKB_CB(skb)->flags |= IEEE80211_TX_INTFL_DONT_ENCRYPT;
+	IEEE80211_SKB_CB(skb)->flags |= IEEE80211_TX_INTFL_DONT_ENCRYPT |
+					tx_flags;
 	ieee80211_tx_skb(sdata, skb);
 }
 
@@ -1277,7 +1279,7 @@ struct sk_buff *ieee80211_build_probe_req(struct ieee80211_sub_if_data *sdata,
 void ieee80211_send_probe_req(struct ieee80211_sub_if_data *sdata, u8 *dst,
 			      const u8 *ssid, size_t ssid_len,
 			      const u8 *ie, size_t ie_len,
-			      u32 ratemask, bool directed, bool no_cck,
+			      u32 ratemask, bool directed, u32 tx_flags,
 			      struct ieee80211_channel *channel, bool scan)
 {
 	struct sk_buff *skb;
@@ -1286,9 +1288,7 @@ void ieee80211_send_probe_req(struct ieee80211_sub_if_data *sdata, u8 *dst,
 					ssid, ssid_len,
 					ie, ie_len, directed);
 	if (skb) {
-		if (no_cck)
-			IEEE80211_SKB_CB(skb)->flags |=
-				IEEE80211_TX_CTL_NO_CCK_RATE;
+		IEEE80211_SKB_CB(skb)->flags |= tx_flags;
 		if (scan)
 			ieee80211_tx_skb_tid_band(sdata, skb, 7, channel->band);
 		else
-- 
1.8.0

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Johannes Berg]

On Thu, 2013-01-31 at 14:28 +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> When sending authentication/association frames they
> might take a bit of time to go out because we may
> have to synchronise with the AP, in particular in
> the case where it's really a P2P GO. In this case
> the 200ms fixed timeout could potentially be too
> short if the beacon interval is relatively large.
> 
> For drivers that report TX status we can do better.
> Instead of starting the timeout directly, start it
> only when the frame status arrives. Since then the
> frame was out on the air, we can wait shorter (the
> typical response time is supposed to be 30ms, wait
> 100ms.) Also, if the frame failed to be transmitted
> try again right away instead of waiting.

Applied.

johannes

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Wojciech Dubowik]

[-- Attachment #1: Type: text/plain, Size: 1499 bytes --]

There is a regression introduced with this patch.
On my ath9k AP + ath9k STA I get timeout for
management frames even when they are acked.

Attached syslog and iw event before and after
this patch.

I have seen it before in my testing and it gets
a lot worse with system load.  Sometimes it can
retry auth/assoc frames for 10 seconds before
connecting.
Anyway it always looses the first authentication frame.

Wojtek


On 02/04/2013 04:43 PM, Johannes Berg wrote:
> On Thu, 2013-01-31 at 14:28 +0100, Johannes Berg wrote:
>> From: Johannes Berg <johannes.berg@intel.com>
>>
>> When sending authentication/association frames they
>> might take a bit of time to go out because we may
>> have to synchronise with the AP, in particular in
>> the case where it's really a P2P GO. In this case
>> the 200ms fixed timeout could potentially be too
>> short if the beacon interval is relatively large.
>>
>> For drivers that report TX status we can do better.
>> Instead of starting the timeout directly, start it
>> only when the frame status arrives. Since then the
>> frame was out on the air, we can wait shorter (the
>> typical response time is supposed to be 30ms, wait
>> 100ms.) Also, if the frame failed to be transmitted
>> try again right away instead of waiting.
> Applied.
>
> johannes
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html


[-- Attachment #2: regression.txt --]
[-- Type: text/plain, Size: 6282 bytes --]

[before commit mac80211: start auth/assoc timeout on frame status]
*syslog*
Feb 13 14:33:33 wlanTS kernel: [ 5486.324069] device wlan1 entered promiscuous mode
Feb 13 14:33:33 wlanTS kernel: [ 5486.335067] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
Feb 13 14:33:33 wlanTS kernel: [ 5486.346850] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
Feb 13 14:33:33 wlanTS kernel: [ 5486.346869] wlan_br: port 1(wlan1) entered forwarding state
Feb 13 14:33:33 wlanTS kernel: [ 5486.346871] wlan_br: port 1(wlan1) entered forwarding state
Feb 13 14:33:38 wlanTS kernel: [ 5491.355402] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Feb 13 14:33:41 wlanTS kernel: [ 5494.074674] wlan0: authenticate with 04:f0:21:02:46:46
Feb 13 14:33:41 wlanTS kernel: [ 5494.077644] wlan0: send auth to 04:f0:21:02:46:46 (try 1/3)
Feb 13 14:33:41 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 802.11: authenticated
Feb 13 14:33:41 wlanTS kernel: [ 5494.099724] wlan0: authenticated
Feb 13 14:33:41 wlanTS kernel: [ 5494.100285] ath9k 0000:01:00.0 wlan0: disabling HT as WMM/QoS is not supported by the AP
Feb 13 14:33:41 wlanTS kernel: [ 5494.100290] ath9k 0000:01:00.0 wlan0: disabling VHT as WMM/QoS is not supported by the AP
Feb 13 14:33:41 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 802.11: associated (aid 1)
Feb 13 14:33:41 wlanTS kernel: [ 5494.104142] wlan0: associate with 04:f0:21:02:46:46 (try 1/3)
Feb 13 14:33:41 wlanTS kernel: [ 5494.107731] wlan0: RX AssocResp from 04:f0:21:02:46:46 (capab=0x11 status=0 aid=1)
Feb 13 14:33:41 wlanTS kernel: [ 5494.107800] wlan0: associated
Feb 13 14:33:41 wlanTS kernel: [ 5494.109144] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Feb 13 14:33:41 wlanTS kernel: [ 5494.115996] wlan0: dropped frame to 04:f0:21:02:46:46 (unauthorized port)
Feb 13 14:33:41 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 RADIUS: starting accounting session 511B962D-00000000
Feb 13 14:33:41 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 WPA: pairwise key handshake completed (RSN)
Feb 13 14:33:48 wlanTS kernel: [ 5501.372049] wlan_br: port 1(wlan1) entered forwarding state
*iw event*
1360762419.008893: wlan0 (phy #0): scan started
1360762421.616111: wlan0 (phy #0): scan finished: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540 5560 5580 5660 5680 5700 5745 5765 5785 5805 5825, ""
1360762421.618919: wlan0: new station 04:f0:21:02:46:46
1360762421.640630: wlan1 (phy #1): mgmt TX status (cookie ffff8801fe4ca100): acked
1360762421.641175: wlan0 (phy #0): auth 04:f0:21:02:46:46 -> 04:f0:21:02:46:45 status: 0: Successful [frame: b0 00 2c 00 04 f0 21 02 46 45 04 f0 21 02 46 46 04 f0 21 02 46 46 f0 0b 00 00 02 00 00 00]
1360762421.646460: wlan1 (phy #1): mgmt TX status (cookie ffff8801c40fe900): acked
1360762421.648709: wlan1: new station 04:f0:21:02:46:45
1360762421.649241: wlan0 (phy #0): assoc 04:f0:21:02:46:46 -> 04:f0:21:02:46:45 status: 0: Successful [frame: 10 00 2c 00 04 f0 21 02 46 45 04 f0 21 02 46 46 04 f0 21 02 46 46 00 0c 11 00 00 00 01 c0 01 02 b0 c8]
1360762421.650437: wlan0 (phy #0): connected to 04:f0:21:02:46:46


[after commit mac80211: start auth/assoc timeout on frame status]
*syslog*
Feb 13 14:38:53 wlanTS kernel: [ 5805.902369] device wlan1 entered promiscuous mode
Feb 13 14:38:53 wlanTS kernel: [ 5805.906908] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
Feb 13 14:38:53 wlanTS kernel: [ 5805.918510] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
Feb 13 14:38:53 wlanTS kernel: [ 5805.918527] wlan_br: port 1(wlan1) entered forwarding state
Feb 13 14:38:53 wlanTS kernel: [ 5805.918529] wlan_br: port 1(wlan1) entered forwarding state
Feb 13 14:39:01 wlanTS kernel: [ 5813.686051] wlan0: authenticate with 04:f0:21:02:46:46
Feb 13 14:39:01 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 802.11: authenticated
Feb 13 14:39:01 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 802.11: authenticated
Feb 13 14:39:01 wlanTS kernel: [ 5813.690956] wlan0: send auth to 04:f0:21:02:46:46 (try 1/3)
Feb 13 14:39:01 wlanTS kernel: [ 5813.691059] wlan0: send auth to 04:f0:21:02:46:46 (try 2/3)
Feb 13 14:39:01 wlanTS kernel: [ 5813.692707] wlan0: authenticated
Feb 13 14:39:01 wlanTS kernel: [ 5813.694673] ath9k 0000:01:00.0 wlan0: disabling HT as WMM/QoS is not supported by the AP
Feb 13 14:39:01 wlanTS kernel: [ 5813.694674] ath9k 0000:01:00.0 wlan0: disabling VHT as WMM/QoS is not supported by the AP
Feb 13 14:39:01 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 802.11: associated (aid 1)
Feb 13 14:39:01 wlanTS kernel: [ 5813.698424] wlan0: associate with 04:f0:21:02:46:46 (try 1/3)
Feb 13 14:39:01 wlanTS kernel: [ 5813.701154] wlan0: RX AssocResp from 04:f0:21:02:46:46 (capab=0x11 status=0 aid=1)
Feb 13 14:39:01 wlanTS kernel: [ 5813.701187] wlan0: associated
Feb 13 14:39:01 wlanTS kernel: [ 5813.701288] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Feb 13 14:39:01 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 RADIUS: starting accounting session 511B976D-00000000
Feb 13 14:39:01 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 WPA: pairwise key handshake completed (RSN)
*iw event*
1360762738.615338: wlan0 (phy #0): scan started
1360762741.224528: wlan0 (phy #0): scan finished: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540 5560 5580 5660 5680 5700 5745 5765 5785 5805 5825, ""
1360762741.229969: wlan0: new station 04:f0:21:02:46:46
1360762741.231382: wlan1 (phy #1): mgmt TX status (cookie ffff880202b3e500): acked
1360762741.231407: wlan1 (phy #1): mgmt TX status (cookie ffff880202b3e600): acked
1360762741.231898: wlan0 (phy #0): auth 04:f0:21:02:46:46 -> 04:f0:21:02:46:45 status: 0: Successful [frame: b0 00 2c 00 04 f0 21 02 46 45 04 f0 21 02 46 46 04 f0 21 02 46 46 f0 0b 00 00 02 00 00 00]
1360762741.238314: wlan1 (phy #1): mgmt TX status (cookie ffff880202b3e300): acked
1360762741.240121: wlan1: new station 04:f0:21:02:46:45
1360762741.240280: wlan0 (phy #0): assoc 04:f0:21:02:46:46 -> 04:f0:21:02:46:45 status: 0: Successful [frame: 10 00 2c 00 04 f0 21 02 46 45 04 f0 21 02 46 46 04 f0 21 02 46 46 20 0c 11 00 00 00 01 c0 01 02 b0 c8]
1360762741.240326: wlan0 (phy #0): connected to 04:f0:21:02:46:46

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Johannes Berg]

On Wed, 2013-02-13 at 14:41 +0100, Wojciech Dubowik wrote:
> There is a regression introduced with this patch.
> On my ath9k AP + ath9k STA I get timeout for
> management frames even when they are acked.
> 
> Attached syslog and iw event before and after
> this patch.
> 
> I have seen it before in my testing and it gets
> a lot worse with system load.  Sometimes it can
> retry auth/assoc frames for 10 seconds before
> connecting.
> Anyway it always looses the first authentication frame.

I think I see what's happening -- can you try this patch?

http://p.sipsolutions.net/61f4271fed0e446b.txt

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Wojciech Dubowik]

On 02/13/2013 03:21 PM, Johannes Berg wrote:
> On Wed, 2013-02-13 at 14:41 +0100, Wojciech Dubowik wrote:
>> There is a regression introduced with this patch.
>> On my ath9k AP + ath9k STA I get timeout for
>> management frames even when they are acked.
>>
>> Attached syslog and iw event before and after
>> this patch.
>>
>> I have seen it before in my testing and it gets
>> a lot worse with system load.  Sometimes it can
>> retry auth/assoc frames for 10 seconds before
>> connecting.
>> Anyway it always looses the first authentication frame.
> I think I see what's happening -- can you try this patch?
>
> http://p.sipsolutions.net/61f4271fed0e446b.txt
>
I have tried and it doesn't do timeout anymore. I will continue
testing with more load.

Thanks,
Wojtek

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Johannes Berg]

On Wed, 2013-02-13 at 15:23 +0100, Wojciech Dubowik wrote:

> >> I have seen it before in my testing and it gets
> >> a lot worse with system load.  Sometimes it can
> >> retry auth/assoc frames for 10 seconds before
> >> connecting.
> >> Anyway it always looses the first authentication frame.
> > I think I see what's happening -- can you try this patch?
> >
> > http://p.sipsolutions.net/61f4271fed0e446b.txt
> >
> I have tried and it doesn't do timeout anymore. I will continue
> testing with more load.

Ok. I just realized that it needs to receive frames for this to happen,
which may not happen here because my environment is quiet.

Let me know, I'll also try to test a bit more.

johannes

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Johannes Berg]

On Wed, 2013-02-13 at 15:32 +0100, Johannes Berg wrote:
> On Wed, 2013-02-13 at 15:23 +0100, Wojciech Dubowik wrote:
> 
> > >> I have seen it before in my testing and it gets
> > >> a lot worse with system load.  Sometimes it can
> > >> retry auth/assoc frames for 10 seconds before
> > >> connecting.
> > >> Anyway it always looses the first authentication frame.
> > > I think I see what's happening -- can you try this patch?
> > >
> > > http://p.sipsolutions.net/61f4271fed0e446b.txt
> > >
> > I have tried and it doesn't do timeout anymore. I will continue
> > testing with more load.
> 
> Ok. I just realized that it needs to receive frames for this to happen,
> which may not happen here because my environment is quiet.
> 
> Let me know, I'll also try to test a bit more.

Yep, I can reproduce it when I make the beacon interval very short and
also let hostapd delay the auth and/or assoc response by 30ms. This
patch fixes it for me, let me know how it goes in your test.

johannes

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Wojciech Dubowik]

On 02/13/2013 03:39 PM, Johannes Berg wrote:
> On Wed, 2013-02-13 at 15:32 +0100, Johannes Berg wrote:
>> On Wed, 2013-02-13 at 15:23 +0100, Wojciech Dubowik wrote:
>>
>>>>> I have seen it before in my testing and it gets
>>>>> a lot worse with system load.  Sometimes it can
>>>>> retry auth/assoc frames for 10 seconds before
>>>>> connecting.
>>>>> Anyway it always looses the first authentication frame.
>>>> I think I see what's happening -- can you try this patch?
>>>>
>>>> http://p.sipsolutions.net/61f4271fed0e446b.txt
>>>>
>>> I have tried and it doesn't do timeout anymore. I will continue
>>> testing with more load.
>> Ok. I just realized that it needs to receive frames for this to happen,
>> which may not happen here because my environment is quiet.
>>
>> Let me know, I'll also try to test a bit more.
> Yep, I can reproduce it when I make the beacon interval very short and
> also let hostapd delay the auth and/or assoc response by 30ms. This
> patch fixes it for me, let me know how it goes in your test.
I don't see anymore timeouts. Sometimes station tries to authenticate,
sends direct probe, timeouts and then goes again with auth message.

Sth like this
Feb 13 16:17:36 wlanTS kernel: [11729.443501] wlan_br: port 1(wlan1) 
entered forwarding state
Feb 13 16:17:41 wlanTS kernel: [11734.434151] IPv6: ADDRCONF(NETDEV_UP): 
wlan0: link is not ready
Feb 13 16:17:44 wlanTS kernel: [11736.961229] wlan0: authenticate with 
04:f0:21:02:46:46
Feb 13 16:17:44 wlanTS kernel: [11736.961237] wlan0: 
capabilities/regulatory prevented using AP HT/VHT configuration, downgraded
Feb 13 16:17:44 wlanTS kernel: [11736.961379] wlan0: direct probe to 
04:f0:21:02:46:46 (try 1/3)
Feb 13 16:17:51 wlanTS kernel: [11744.489664] wlan_br: port 1(wlan1) 
entered forwarding state
Feb 13 16:17:54 wlanTS kernel: [11746.962003] wlan0: deauthenticating 
from 04:f0:21:02:46:46 by local choice (reason=3)
Feb 13 16:17:57 wlanTS kernel: [11750.388480] wlan0: authenticate with 
04:f0:21:02:46:46
Feb 13 16:17:57 wlanTS kernel: [11750.388483] wlan0: 
capabilities/regulatory prevented using AP HT/VHT configuration, downgraded
Feb 13 16:17:57 wlanTS kernel: [11750.388538] wlan0: send auth to 
04:f0:21:02:46:46 (try 1/3)
Feb 13 16:17:57 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 
802.11: authenticated
Feb 13 16:17:57 wlanTS kernel: [11750.425317] wlan0: authenticated
Feb 13 16:17:57 wlanTS kernel: [11750.425379] ath9k 0000:01:00.0 wlan0: 
disabling HT as WMM/QoS is not supported by the AP
Feb 13 16:17:57 wlanTS kernel: [11750.425381] ath9k 0000:01:00.0 wlan0: 
disabling VHT as WMM/QoS is not supported by the AP
Feb 13 16:17:57 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 IEEE 
802.11: associated (aid 1)
Feb 13 16:17:57 wlanTS kernel: [11750.425893] wlan0: associate with 
04:f0:21:02:46:46 (try 1/3)
Feb 13 16:17:57 wlanTS kernel: [11750.430009] wlan0: RX AssocResp from 
04:f0:21:02:46:46 (capab=0x11 status=0 aid=1)
Feb 13 16:17:57 wlanTS kernel: [11750.430077] wlan0: associated
Feb 13 16:17:57 wlanTS kernel: [11750.430459] IPv6: 
ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Feb 13 16:17:57 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 RADIUS: 
starting accounting session 511BAE90-00000000
Feb 13 16:17:57 wlanTS hostapd: wlan1: STA 04:f0:21:02:46:45 WPA: 
pairwise key handshake completed (RSN)

I still get beacon miss events but it seems it's somehow
connected with BI. For 15ms I get is sporadically but for
25,30,35 I get it every second.
For 40ms I still get it sporadically and for default 100ms
I don't see it at all.
Strange...

I will try to put some printk to see what's going on. It's
probably not related to this patch.

Wojtek
>

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Sujith Manoharan]

Wojciech Dubowik wrote:
> I don't see anymore timeouts. Sometimes station tries to authenticate,
> sends direct probe, timeouts and then goes again with auth message.

If you are using ath9k_rate_control, can you check if you still see the issue
with minstrel_ht ?

Sujith

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Wojciech Dubowik]

On 02/13/2013 04:36 PM, Sujith Manoharan wrote:
> Wojciech Dubowik wrote:
>> I don't see anymore timeouts. Sometimes station tries to authenticate,
>> sends direct probe, timeouts and then goes again with auth message.
> If you are using ath9k_rate_control, can you check if you still see the issue
> with minstrel_ht ?
I am using minstrel.

The above problem actually came from my  setup. I was using
my hostpad with trial support for ap_scan=2, that's what I am
trying to work on now. My test scripts are not very mature yet...

With stock hostapd and ap_scan=1 it seems to work quite
fine.

Wojtek

Re: [PATCH] mac80211: start auth/assoc timeout on frame status

[Johannes Berg]

On Wed, 2013-02-13 at 16:41 +0100, Wojciech Dubowik wrote:
> On 02/13/2013 04:36 PM, Sujith Manoharan wrote:
> > Wojciech Dubowik wrote:
> >> I don't see anymore timeouts. Sometimes station tries to authenticate,
> >> sends direct probe, timeouts and then goes again with auth message.
> > If you are using ath9k_rate_control, can you check if you still see the issue
> > with minstrel_ht ?
> I am using minstrel.
> 
> The above problem actually came from my  setup. I was using
> my hostpad with trial support for ap_scan=2, that's what I am
> trying to work on now. My test scripts are not very mature yet...
> 
> With stock hostapd and ap_scan=1 it seems to work quite
> fine.

Ok. Can I add your tested-by?

johannes