Management abstrace: NL80211 is now much butter then WEXT :-)
wireless-testing GIT with the "don't overwrite security" patch
and wpa_supplicant git.
I made logs with
script -c "./wpa_supplicant -i eth1 -D nl80211 -t -c wpa.conf -d" wext_nl80211
script -c "./wpa_supplicant -i eth1 -D nl80211 -t -c wpa.conf -d" wpa_nl8021
script -c "./wpa_supplicant -i eth1 -D wext -t -c wep.conf -d" wep_wext
script -c "./wpa_supplicant -i eth1 -D wext -t -c wep.conf -d" wep_wext
Then I wrote a little python script to sift throught the weeds,
extract interesting events and get me the time since start and
time since previous event.
Some of those "interesting" events are further marked as
"##ERROR" to stand out from the log.
wep_wext
--------
0.00000 0.00000: Initializing interface ...
0.08801 0.08801: Setting scan request: 0 sec 100000 usec
0.25167 0.16365: ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
0.25171 0.00005: ##ERROR: Failed to get scan results
0.25172 0.00001: ##ERROR: Failed to get scan results - try scanning again
0.25173 0.00001: Setting scan request: 0 sec 0 usec
0.25176 0.00003: ioctl[SIOCSIWSCAN]: Device or resource busy
0.25179 0.00003: ##ERROR: Failed to initiate AP scan.
0.25180 0.00001: Setting scan request: 10 sec 0 usec
3.07458 2.82278: CTRL-EVENT-CONNECTED - Connection to 00:1b:d4:44:35:90 completed (auth) [id=0 id_str=]
wep_nl80211
-----------
0.00000 0.00000: Initializing interface ...
0.03985 0.03985: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.03992 0.00007: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.03998 0.00006: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.04004 0.00006: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.04008 0.00004: Setting scan request: 0 sec 100000 usec
0.14061 0.10053: Received scan results (0 BSSes)
0.14070 0.00009: Setting scan request: 0 sec 0 usec
0.78813 0.64743: Received scan results (5 BSSes)
0.78853 0.00040: Trying to authenticate with 00:1b:53:11:dc:40 (SSID='MNFUNK' freq=2412 MHz)
0.78888 0.00034: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.96270 0.17382: SME: Authentication response: peer=00:1b:53:11:dc:40 auth_type=0 status_code=0
wpa_wext
--------
0.00000 0.00000: Initializing interface ...
0.07409 0.07409: Setting scan request: 0 sec 100000 usec
0.24986 0.17576: ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
0.24990 0.00004: ##ERROR: Failed to get scan results
0.24991 0.00001: ##ERROR: Failed to get scan results - try scanning again
0.24991 0.00001: Setting scan request: 0 sec 0 usec
0.24995 0.00003: ioctl[SIOCSIWSCAN]: Device or resource busy
0.24998 0.00003: ##ERROR: Failed to initiate AP scan.
0.24998 0.00001: Setting scan request: 10 sec 0 usec
3.15609 2.90611: CTRL-EVENT-CONNECTED - Connection to 00:1b:d4:44:35:90 completed (auth) [id=0 id_str=]
wpa_nl80211
-----------
0.00000 0.00000: Initializing interface ...
0.07400 0.07400: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.07406 0.00007: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.07413 0.00006: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.07419 0.00006: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
0.07424 0.00005: Setting scan request: 0 sec 100000 usec
0.17475 0.10052: Received scan results (0 BSSes)
0.17485 0.00009: Setting scan request: 0 sec 0 usec
0.67432 0.49947: Received scan results (3 BSSes)
0.67463 0.00032: Trying to authenticate with 00:1b:d4:44:35:90 (SSID='MNWPA' freq=2412 MHz)
0.81141 0.13678: SME: Authentication response: peer=00:1b:d4:44:35:90 auth_type=0 status_code=0
0.98805 0.17664: CTRL-EVENT-CONNECTED - Connection to 00:1b:d4:44:35:90 completed (auth) [id=0 id_str=]
For those tests, it was needed to rmmod mac80211 & friends
between those test, because otherwise connection could take up to
15 seconds.
We've quite a number of errors.
Also, NL80211 is usually faster connecting one than WEXT.
I can't say if this is a property of NL80211, it might also be
because COMPAT-WEXT has still some bugs and produces more errors,
making wpa_supplicant do excessive scanning.
--
http://www.holgerschurig.de
On Wednesday 23 September 2009 09:01:31 Johannes Berg wrote:
> Because the scan request contains info on how to do the scan.
I know. I sent another mail where I said the traceback
was correct, but not my conclusion: I confused
cfg80211_wext_siwscan() and cfg80211_wext_giwscan().
I thougth the return -EBUSY is in cfg80211_wext_giwscan().
That it is in cfg80211_wext_siwscan() makes perfect sense.
--
http://www.holgerschurig.de
On Tue, 2009-09-22 at 11:18 +0200, Holger Schurig wrote:
> wep_nl80211
> -----------
> 0.00000 0.00000: Initializing interface ...
> 0.03985 0.03985: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
Those are expected, and ok.
johannes
> However, I'm wondering: if several scan commands are
> ...
Ah, the analysis was correct, but not the conclusion. The -EBUSY
wasn't in cfg80211_wext_giwscan(), but in
cfg80211_wext_siwscan().
Hey, I'm talking too much to myself.
/me wishes, the people are back from PDX to normal work :-)
--
http://www.holgerschurig.de
On Tue, 2009-09-22 at 12:58 +0200, Holger Schurig wrote:
> > 0.00000 0.00000: Initializing interface ...
> > 0.08801 0.08801: Setting scan request: 0 sec 100000 usec
> > 0.25167 0.16365: ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
>
> This is because wpa_supplicant very early - in
> wpa_driver_wext_finish_drv_init() - calls
> wpa_driver_wext_disconnect(). This in turn sets a random 32
> character long ESSID, as a desparate means to disconnect.
>
> Now that an essid is set, the calling chain in the kernel
>
> cfg80211_netdev_notifier_call(), case NETDEV_UP
> cfg80211_mgd_wext_connect()
> __cfg80211_connect()
> cfg80211_conn_scan(
>
> get's executed. This starts a scan.
>
> Later, when wpa_supplicant tries to get a scan result, it will
> only get an -EBUSY because of net/wireless/scan.c, function
> cfg80211_wext_siwscan():
>
> if (rdev->scan_req) {
> err = -EBUSY;
> goto out;
> }
>
>
>
> However, I'm wondering: if several scan commands are
> supposed to add up into the BSS list anyway (and each BSS list
> entry by default pruned after 15 seconds), why is it an error
> to access the current state of the BSS list while a scan is
> in progress?
Because the scan request contains info on how to do the scan.
johannes
On Wed, 2009-09-23 at 09:07 +0200, Holger Schurig wrote:
> > Those are expected, and ok.
>
> Okay, then here is a patch to silence this in wpa_supplicant.
No, they should only be ignored under certain circumstances.
johannes
> Signed-off-by: Holger Schurig <[email protected]>
>
> Index: wpasupplicant/src/drivers/driver_nl80211.c
> ===================================================================
> --- wpasupplicant.orig/src/drivers/driver_nl80211.c 2009-09-22 12:28:58.000000000 +0200
> +++ wpasupplicant/src/drivers/driver_nl80211.c 2009-09-22 12:30:29.000000000 +0200
> @@ -1819,6 +1819,8 @@ static int nl_set_encr(int ifindex, stru
> NLA_PUT_U32(msg, NL80211_ATTR_IFINDEX, ifindex);
>
> ret = send_and_recv_msgs(drv, msg, NULL, NULL);
> + if (ret == -ENOLINK)
> + ret = 0;
> if (ret == -ENOENT && alg == WPA_ALG_NONE)
> ret = 0;
> if (ret)
> @@ -1850,7 +1852,7 @@ static int nl_set_encr(int ifindex, stru
> NLA_PUT_FLAG(msg, NL80211_ATTR_KEY_DEFAULT);
>
> ret = send_and_recv_msgs(drv, msg, NULL, NULL);
> - if (ret == -ENOENT)
> + if (ret == -ENOENT || ret == -ENOLINK)
> ret = 0;
> if (ret)
> wpa_printf(MSG_DEBUG, "nl80211: set_key default failed; "
>
>
>
> wep_nl80211
> -----------
> 0.00000 0.00000: Initializing interface ...
> 0.03985 0.03985: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
> 0.03992 0.00007: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
> 0.03998 0.00006: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
> 0.04004 0.00006: ##ERROR: nl80211: set_key failed; err=-67 Link has been severed)
This is because of net/wireless/nl80211.c, function nl80211_key_allowed():
switch (wdev->iftype) {
...
case NL80211_IFTYPE_STATION:
if (wdev->sme_state != CFG80211_SME_CONNECTED)
return -ENOLINK;
break;
> wep_wext
> --------
> 0.00000 0.00000: Initializing interface ...
> 0.08801 0.08801: Setting scan request: 0 sec 100000 usec
> 0.25167 0.16365: ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
This is because wpa_supplicant very early - in
wpa_driver_wext_finish_drv_init() - calls
wpa_driver_wext_disconnect(). This in turn sets a random 32
character long ESSID, as a desparate means to disconnect.
Now that an essid is set, the calling chain in the kernel
cfg80211_netdev_notifier_call(), case NETDEV_UP
cfg80211_mgd_wext_connect()
__cfg80211_connect()
cfg80211_conn_scan(
get's executed. This starts a scan.
Later, when wpa_supplicant tries to get a scan result, it will
only get an -EBUSY because of net/wireless/scan.c, function
cfg80211_wext_siwscan():
if (rdev->scan_req) {
err = -EBUSY;
goto out;
}
However, I'm wondering: if several scan commands are
supposed to add up into the BSS list anyway (and each BSS list
entry by default pruned after 15 seconds), why is it an error
to access the current state of the BSS list while a scan is
in progress?
In other words, I think the following sequence should be ok:
Request Scan
scan finishes
get scan result (2 BSS entries)
request scan
get scan result (2 BSS entries)
scan finishes (the scan is still in process)
get scan result (5 BSS entries)
If user-space ask for intermediate results, it should be
allowed to do so at any time. If user-space wants full
results, it can wait for the scan-done event.
This would mean that the BSS entries get individual locks
and that rdev->scan_req isn't used as an implicit lock.
--
http://www.holgerschurig.de
> Those are expected, and ok.
Okay, then here is a patch to silence this in wpa_supplicant.
Signed-off-by: Holger Schurig <[email protected]>
Index: wpasupplicant/src/drivers/driver_nl80211.c
===================================================================
--- wpasupplicant.orig/src/drivers/driver_nl80211.c 2009-09-22 12:28:58.000000000 +0200
+++ wpasupplicant/src/drivers/driver_nl80211.c 2009-09-22 12:30:29.000000000 +0200
@@ -1819,6 +1819,8 @@ static int nl_set_encr(int ifindex, stru
NLA_PUT_U32(msg, NL80211_ATTR_IFINDEX, ifindex);
ret = send_and_recv_msgs(drv, msg, NULL, NULL);
+ if (ret == -ENOLINK)
+ ret = 0;
if (ret == -ENOENT && alg == WPA_ALG_NONE)
ret = 0;
if (ret)
@@ -1850,7 +1852,7 @@ static int nl_set_encr(int ifindex, stru
NLA_PUT_FLAG(msg, NL80211_ATTR_KEY_DEFAULT);
ret = send_and_recv_msgs(drv, msg, NULL, NULL);
- if (ret == -ENOENT)
+ if (ret == -ENOENT || ret == -ENOLINK)
ret = 0;
if (ret)
wpa_printf(MSG_DEBUG, "nl80211: set_key default failed; "
--
http://www.holgerschurig.de