attempt to scan fails (device busy) if essid/ssid was changed recently

attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

Recently I was trying to reduce time it takes for wireless card to
connect.

I noticed that always first attempt at scan fails when NM asks for scan.
I also noticed that this happens with quite recent kernels (I think
2,6.28) didn't have this behavior.

Looking a bit deeper I discovered that each time NM disconnects from a
networks it sets random ssid/essid to the card (using wireless
extensions)

After that scan fails for some time.

as a NM free example you can run 

iwconfig wlan0 essid dummy
iwlist scan


and this will fail



NM in this case waits for whole 10 seconds.


What do you think about this?

I confirm that on iwl3945 and ath5k, so this isn't driver specific.

Best regards,
	Maxim Levitsky

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Tue, 2009-04-07 at 03:00 +0300, Maxim Levitsky wrote:

> I noticed that always first attempt at scan fails when NM asks for scan.
> I also noticed that this happens with quite recent kernels (I think
> 2,6.28) didn't have this behavior.

I'm pretty sure it did.

> Looking a bit deeper I discovered that each time NM disconnects from a
> networks it sets random ssid/essid to the card (using wireless
> extensions)

This forces a scan

> After that scan fails for some time.
> 
> as a NM free example you can run 
> 
> iwconfig wlan0 essid dummy
> iwlist scan

and then this fails with EBUSY.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Tue, 2009-04-07 at 10:18 +0200, Johannes Berg wrote:
> On Tue, 2009-04-07 at 03:00 +0300, Maxim Levitsky wrote:
> 
> > I noticed that always first attempt at scan fails when NM asks for scan.
> > I also noticed that this happens with quite recent kernels (I think
> > 2,6.28) didn't have this behavior.
> 
> I'm pretty sure it did.
I am sure that on older kernel there was no -EBUSY error returned to
userspace. It probably just stalled the client.


> 
> > Looking a bit deeper I discovered that each time NM disconnects from a
> > networks it sets random ssid/essid to the card (using wireless
> > extensions)
> 
> This forces a scan
> 
> > After that scan fails for some time.
> > 
> > as a NM free example you can run 
> > 
> > iwconfig wlan0 essid dummy
> > iwlist scan
> 
> and then this fails with EBUSY.
Thanks for explanation.
Since NM has its reasons to clear essid (to prevent unwanted
association), then what can be  done to prevent this (and still use
wireless extensions, since nl80211 support isn't yet mature)?


Best regards,
	Maxim Levitsky

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Tue, 2009-04-07 at 15:51 +0300, Maxim Levitsky wrote:

> > > I noticed that always first attempt at scan fails when NM asks for scan.
> > > I also noticed that this happens with quite recent kernels (I think
> > > 2,6.28) didn't have this behavior.
> > 
> > I'm pretty sure it did.

> I am sure that on older kernel there was no -EBUSY error returned to
> userspace. It probably just stalled the client.

Can't imagine it did, maybe it just dropped the request though without
indicating an error.

> > > Looking a bit deeper I discovered that each time NM disconnects from a
> > > networks it sets random ssid/essid to the card (using wireless
> > > extensions)
> > 
> > This forces a scan
> > 
> > > After that scan fails for some time.
> > > 
> > > as a NM free example you can run 
> > > 
> > > iwconfig wlan0 essid dummy
> > > iwlist scan
> > 
> > and then this fails with EBUSY.
> Thanks for explanation.
> Since NM has its reasons to clear essid (to prevent unwanted
> association), then what can be  done to prevent this (and still use
> wireless extensions, since nl80211 support isn't yet mature)?

Nothing. Wext sucks, news at 11, yadda.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Tue, 2009-04-07 at 14:56 +0200, Johannes Berg wrote:
> On Tue, 2009-04-07 at 15:51 +0300, Maxim Levitsky wrote:
> 
> > > > I noticed that always first attempt at scan fails when NM asks for scan.
> > > > I also noticed that this happens with quite recent kernels (I think
> > > > 2,6.28) didn't have this behavior.
> > > 
> > > I'm pretty sure it did.
> 
> > I am sure that on older kernel there was no -EBUSY error returned to
> > userspace. It probably just stalled the client.
> 
> Can't imagine it did, maybe it just dropped the request though without
> indicating an error.
Very likely.

> 
> > > > Looking a bit deeper I discovered that each time NM disconnects from a
> > > > networks it sets random ssid/essid to the card (using wireless
> > > > extensions)
> > > 
> > > This forces a scan
> > > 
> > > > After that scan fails for some time.
> > > > 
> > > > as a NM free example you can run 
> > > > 
> > > > iwconfig wlan0 essid dummy
> > > > iwlist scan
> > > 
> > > and then this fails with EBUSY.
> > Thanks for explanation.
> > Since NM has its reasons to clear essid (to prevent unwanted
> > association), then what can be  done to prevent this (and still use
> > wireless extensions, since nl80211 support isn't yet mature)?
> 
> Nothing. Wext sucks, news at 11, yadda.
Thanks.
Everything understood.


Best regards,
	Maxim Levitsky

> 
> johannes

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Tue, 2009-04-07 at 16:04 +0300, Maxim Levitsky wrote:

> > > > > Looking a bit deeper I discovered that each time NM disconnects from a
> > > > > networks it sets random ssid/essid to the card (using wireless
> > > > > extensions)
> > > > 
> > > > This forces a scan
> > > > 
> > > > > After that scan fails for some time.
> > > > > 
> > > > > as a NM free example you can run 
> > > > > 
> > > > > iwconfig wlan0 essid dummy
> > > > > iwlist scan
> > > > 
> > > > and then this fails with EBUSY.
> > > Thanks for explanation.
> > > Since NM has its reasons to clear essid (to prevent unwanted
> > > association), then what can be  done to prevent this (and still use
> > > wireless extensions, since nl80211 support isn't yet mature)?
> > 
> > Nothing. Wext sucks, news at 11, yadda.
> Thanks.
> Everything understood.

Of course, we can go back to dropping the scan request, but that
wouldn't be very nice.

Is this creating any problems?

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Tue, 2009-04-07 at 15:13 +0200, Johannes Berg wrote:
> On Tue, 2009-04-07 at 16:04 +0300, Maxim Levitsky wrote:
> 
> > > > > > Looking a bit deeper I discovered that each time NM disconnects from a
> > > > > > networks it sets random ssid/essid to the card (using wireless
> > > > > > extensions)
> > > > > 
> > > > > This forces a scan
> > > > > 
> > > > > > After that scan fails for some time.
> > > > > > 
> > > > > > as a NM free example you can run 
> > > > > > 
> > > > > > iwconfig wlan0 essid dummy
> > > > > > iwlist scan
> > > > > 
> > > > > and then this fails with EBUSY.
> > > > Thanks for explanation.
> > > > Since NM has its reasons to clear essid (to prevent unwanted
> > > > association), then what can be  done to prevent this (and still use
> > > > wireless extensions, since nl80211 support isn't yet mature)?
> > > 
> > > Nothing. Wext sucks, news at 11, yadda.
> > Thanks.
> > Everything understood.
> 
> Of course, we can go back to dropping the scan request, but that
> wouldn't be very nice.
> 
> Is this creating any problems?
Yep, but dropping the request won't help ether.
Problem is that wpa_supplicant will attempt to scan before association,
scan fails (it doesn't know it is already running) thus it waits 10
seconds. (I patched it to wait 2 seconds).

It happens if user first disconnects, and then reconnects to a network
(typical test I do for time it takes to connect)

Now I patched it not to clear essid on disconnect, and this helped
reduce connect times by about 2 seconds.

now it takes just 3~4 seconds to connect to open network, and ~6 seconds
to WPA2 network.

(This is with patched dhclient, I reduced its timeouts, but this is
another story.... it seems that first DHCPREQUEST never succeeds, and I
tested this with 2 cards, and few wireless networks)


Best regards,
	Maxim Levitsky

> 
> johannes

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Tue, 2009-04-07 at 16:20 +0300, Maxim Levitsky wrote:

> > Of course, we can go back to dropping the scan request, but that
> > wouldn't be very nice.
> > 
> > Is this creating any problems?

> Yep, but dropping the request won't help ether.

Indeed.

> Problem is that wpa_supplicant will attempt to scan before association,
> scan fails (it doesn't know it is already running) thus it waits 10
> seconds. (I patched it to wait 2 seconds).
> 
> It happens if user first disconnects, and then reconnects to a network
> (typical test I do for time it takes to connect)
> 
> Now I patched it not to clear essid on disconnect, and this helped
> reduce connect times by about 2 seconds.
> 
> now it takes just 3~4 seconds to connect to open network, and ~6 seconds
> to WPA2 network.
> 
> (This is with patched dhclient, I reduced its timeouts, but this is
> another story.... it seems that first DHCPREQUEST never succeeds, and I
> tested this with 2 cards, and few wireless networks)

Have you tried with a new tree and wpa_supplicant's (from git) nl80211
driver? Might be a lot better.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Tue, 2009-04-07 at 15:27 +0200, Johannes Berg wrote:
> On Tue, 2009-04-07 at 16:20 +0300, Maxim Levitsky wrote:
> 
> > > Of course, we can go back to dropping the scan request, but that
> > > wouldn't be very nice.
> > > 
> > > Is this creating any problems?
> 
> > Yep, but dropping the request won't help ether.
> 
> Indeed.
> 
> > Problem is that wpa_supplicant will attempt to scan before association,
> > scan fails (it doesn't know it is already running) thus it waits 10
> > seconds. (I patched it to wait 2 seconds).
> > 
> > It happens if user first disconnects, and then reconnects to a network
> > (typical test I do for time it takes to connect)
> > 
> > Now I patched it not to clear essid on disconnect, and this helped
> > reduce connect times by about 2 seconds.
> > 
> > now it takes just 3~4 seconds to connect to open network, and ~6 seconds
> > to WPA2 network.
> > 
> > (This is with patched dhclient, I reduced its timeouts, but this is
> > another story.... it seems that first DHCPREQUEST never succeeds, and I
> > tested this with 2 cards, and few wireless networks)
> 
> Have you tried with a new tree and wpa_supplicant's (from git) nl80211
> driver? Might be a lot better.
I use NM and wpa_supplicant from -git
Last time, I tried nl80211 wpa_supplicant driver it didn't work well,
but I try again soon I  hope.
 

Best regards,
	Maxim Levitsky
> 
> johannes

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Tue, 2009-04-07 at 16:51 +0300, Maxim Levitsky wrote:
> On Tue, 2009-04-07 at 15:27 +0200, Johannes Berg wrote:
> > On Tue, 2009-04-07 at 16:20 +0300, Maxim Levitsky wrote:
> > 
> > > > Of course, we can go back to dropping the scan request, but that
> > > > wouldn't be very nice.
> > > > 
> > > > Is this creating any problems?
> > 
> > > Yep, but dropping the request won't help ether.
> > 
> > Indeed.
> > 
> > > Problem is that wpa_supplicant will attempt to scan before association,
> > > scan fails (it doesn't know it is already running) thus it waits 10
> > > seconds. (I patched it to wait 2 seconds).
> > > 
> > > It happens if user first disconnects, and then reconnects to a network
> > > (typical test I do for time it takes to connect)
> > > 
> > > Now I patched it not to clear essid on disconnect, and this helped
> > > reduce connect times by about 2 seconds.
> > > 
> > > now it takes just 3~4 seconds to connect to open network, and ~6 seconds
> > > to WPA2 network.
> > > 
> > > (This is with patched dhclient, I reduced its timeouts, but this is
> > > another story.... it seems that first DHCPREQUEST never succeeds, and I
> > > tested this with 2 cards, and few wireless networks)
> > 
> > Have you tried with a new tree and wpa_supplicant's (from git) nl80211
> > driver? Might be a lot better.
> I use NM and wpa_supplicant from -git
> Last time, I tried nl80211 wpa_supplicant driver it didn't work well,
> but I try again soon I  hope.

I have just tried the nl80211 driver.


First I get this in kernel logs:


> [   29.971903] WARNING: at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79 nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> [   29.971905] Hardware name: Aspire 5720     
> [   29.971906] Modules linked in: nfsd exportfs ipv6 nfs lockd nfs_acl auth_rpcgss sunrpc cpufreq_powersave cpufreq_conservative cpufreq_userspace acpi_cpufreq coretemp sbp2 uvcvideo videodev v4l1_compat v4l2_compat_ioctl32 joydev iwl3945 iwlcore rfkill uhci_hcd mac80211 snd_hda_codec_realtek psmouse lib80211 video snd_hda_intel snd_hda_codec iTCO_wdt tg3 serio_raw ehci_hcd snd_hwdep snd_pcm_oss snd_mixer_oss sdhci_pci iTCO_vendor_support libphy output cfg80211 ata_piix sdhci nvidia(P) evdev ohci1394 snd_pcm snd_timer snd_page_alloc usbcore ext3 jbd mbcache fuse ahci libata
> [   29.971936] Pid: 3688, comm: wpa_supplicant Tainted: P           2.6.29-wl #18
> [   29.971938] Call Trace:
> [   29.971948]  [<ffffffff80241320>] warn_slowpath+0xd0/0x130
> [   29.971956]  [<ffffffffa08e4ac6>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> [   29.971960]  [<ffffffff802a8263>] ? __alloc_pages_internal+0xe3/0x4f0
> [   29.971965]  [<ffffffff804ade47>] ? netdev_run_todo+0x57/0x260
> [   29.971972]  [<ffffffffa08e465d>] nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]
> [   29.971979]  [<ffffffffa08e4ac6>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> [   29.971981]  [<ffffffff802a86ee>] ? __get_free_pages+0x1e/0x60
> [   29.971986]  [<ffffffff804a59ae>] ? __alloc_skb+0x6e/0x140
> [   29.971993]  [<ffffffffa08e4ae4>] nl80211_get_wiphy+0x74/0xd0 [cfg80211]
> [   29.972020]  [<ffffffff804c5986>] genl_rcv_msg+0x1b6/0x1f0
> [   29.972023]  [<ffffffff804c57d0>] ? genl_rcv_msg+0x0/0x1f0
> [   29.972027]  [<ffffffff804c4839>] netlink_rcv_skb+0x89/0xb0
> [   29.972030]  [<ffffffff804c57b7>] genl_rcv+0x27/0x40
> [   29.972032]  [<ffffffff804c4234>] netlink_unicast+0x2c4/0x2e0
> [   29.972035]  [<ffffffff804a59ae>] ? __alloc_skb+0x6e/0x140
> [   29.972038]  [<ffffffff804c4464>] netlink_sendmsg+0x214/0x310
> [   29.972041]  [<ffffffff8049ceb7>] sock_sendmsg+0x127/0x140
> [   29.972045]  [<ffffffff80258c20>] ? autoremove_wake_function+0x0/0x40
> [   29.972049]  [<ffffffff802da0c7>] ? do_lookup+0x147/0x260
> [   29.972052]  [<ffffffff802e375c>] ? dput+0xac/0x160
> [   29.972054]  [<ffffffff8049dd17>] ? move_addr_to_kernel+0x57/0x60
> [   29.972057]  [<ffffffff804a6e7c>] ? verify_iovec+0x3c/0xd0
> [   29.972060]  [<ffffffff8049d059>] sys_sendmsg+0x189/0x320
> [   29.972063]  [<ffffffff8049bf71>] ? sock_ioctl+0x81/0x270
> [   29.972065]  [<ffffffff802dfd21>] ? vfs_ioctl+0x31/0xa0
> [   29.972068]  [<ffffffff802dfe18>] ? do_vfs_ioctl+0x88/0x580
> [   29.972071]  [<ffffffff802d20c9>] ? __fput+0x169/0x1e0
> [   29.972074]  [<ffffffff802e03a9>] ? sys_ioctl+0x99/0xa0
> [   29.972077]  [<ffffffff8020c5db>] system_call_fastpath+0x16/0x1b
> [   29.972079] ---[ end trace b4d9e95705d7d0d8 ]---
> 
> 
> 
Then same -EBUSY errors are present, and this driver even says explictly this.
(This is despite the fact I removed the essid clearing from the wpa_supplicant)
In fact (now I speak about the wext driver) I put printfs in many its functions, and it seems that it only resets encryption keys
before scanning now, and still device seems to be busy.
This ensures that scan occurs twice, and adds up 2~3 seconds to association time, which consists about 40% of all time (~7 seconds)


>  
> 
> Best regards,
> 	Maxim Levitsky
> > 
> > johannes
> 

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Tue, 2009-04-07 at 23:24 +0300, Maxim Levitsky wrote:

> First I get this in kernel logs:
> 
> 
> > [   29.971903] WARNING:
> at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79
> nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()

Eh, I don't think that is present in a recent wireless tree.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Tue, 2009-04-07 at 22:37 +0200, Johannes Berg wrote:
> On Tue, 2009-04-07 at 23:24 +0300, Maxim Levitsky wrote:
> 
> > First I get this in kernel logs:
> > 
> > 
> > > [   29.971903] WARNING:
> > at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79
> > nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> 
> Eh, I don't think that is present in a recent wireless tree.

It is.

I have just compiled iwlwifi.git tree, and same message is there:



> [ 1666.298390] ------------[ cut here ]------------
> [ 1666.298395] WARNING: at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79 nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> [ 1666.298399] Hardware name: Aspire 5720     
> [ 1666.298402] Modules linked in: af_packet nfsd exportfs ipv6 nfs lockd nfs_acl auth_rpcgss sunrpc cpufreq_powersave cpufreq_conservative cpufreq_userspace acpi_cpufreq coretemp sbp2 joydev uvcvideo iwl3945 videodev v4l1_compat v4l2_compat_ioctl32 iwlcore rfkill snd_hda_codec_realtek snd_hda_intel snd_hda_codec mac80211 snd_hwdep ehci_hcd psmouse video iTCO_wdt lib80211 tg3 snd_pcm_oss snd_mixer_oss usbcore output evdev iTCO_vendor_support nvidia(P) cfg80211 libphy serio_raw snd_pcm snd_timer ricoh_mmc sdhci_pci sdhci ohci1394 ata_piix snd_page_alloc ext3 jbd mbcache fuse ahci libata
> [ 1666.298473] Pid: 13164, comm: wpa_supplicant Tainted: P           2.6.29-wl #19
> [ 1666.298477] Call Trace:
> [ 1666.298490]  [<ffffffff80241320>] warn_slowpath+0xd0/0x130
> [ 1666.298504]  [<ffffffffa00f9ac6>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> [ 1666.298512]  [<ffffffff802a8263>] ? __alloc_pages_internal+0xe3/0x4f0
> [ 1666.298525]  [<ffffffffa00f965d>] nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]
> [ 1666.298537]  [<ffffffffa00f9ac6>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> [ 1666.298542]  [<ffffffff802a86ee>] ? __get_free_pages+0x1e/0x60
> [ 1666.298550]  [<ffffffff804a59ae>] ? __alloc_skb+0x6e/0x140
> [ 1666.298562]  [<ffffffffa00f9ae4>] nl80211_get_wiphy+0x74/0xd0 [cfg80211]
> [ 1666.298569]  [<ffffffff804c5986>] genl_rcv_msg+0x1b6/0x1f0
> [ 1666.298575]  [<ffffffff804c57d0>] ? genl_rcv_msg+0x0/0x1f0
> [ 1666.298582]  [<ffffffff804c4839>] netlink_rcv_skb+0x89/0xb0
> [ 1666.298586]  [<ffffffff804c57b7>] genl_rcv+0x27/0x40
> [ 1666.298592]  [<ffffffff804c4234>] netlink_unicast+0x2c4/0x2e0
> [ 1666.298597]  [<ffffffff804a59ae>] ? __alloc_skb+0x6e/0x140
> [ 1666.298603]  [<ffffffff804c4464>] netlink_sendmsg+0x214/0x310
> [ 1666.298609]  [<ffffffff8049ceb7>] sock_sendmsg+0x127/0x140
> [ 1666.298616]  [<ffffffff80258c20>] ? autoremove_wake_function+0x0/0x40
> [ 1666.298622]  [<ffffffff8023bc60>] ? wake_up_process+0x10/0x20
> [ 1666.298629]  [<ffffffff80535c74>] ? __mutex_unlock_slowpath+0x44/0x50
> [ 1666.298635]  [<ffffffff80535c0e>] ? mutex_unlock+0xe/0x10
> [ 1666.298641]  [<ffffffff804b8900>] ? __rtnl_unlock+0x10/0x20
> [ 1666.298647]  [<ffffffff8049dd17>] ? move_addr_to_kernel+0x57/0x60
> [ 1666.298652]  [<ffffffff804a6e7c>] ? verify_iovec+0x3c/0xd0
> [ 1666.298657]  [<ffffffff8049d059>] sys_sendmsg+0x189/0x320
> [ 1666.298663]  [<ffffffff804ffd14>] ? inet_ioctl+0x94/0xc0
> [ 1666.298668]  [<ffffffff8049bf56>] ? sock_ioctl+0x66/0x270
> [ 1666.298675]  [<ffffffff802dfd21>] ? vfs_ioctl+0x31/0xa0
> [ 1666.298680]  [<ffffffff802dfe18>] ? do_vfs_ioctl+0x88/0x580
> [ 1666.298686]  [<ffffffff802d20c9>] ? __fput+0x169/0x1e0
> [ 1666.298692]  [<ffffffff8020c5db>] system_call_fastpath+0x16/0x1b
> [ 1666.298696] ---[ end trace 24eb07dee6e9ca52 ]---
> 
> 

On top of that I need to note that NM doesn't show signal strenghts correctly.
Instead it shows 100% for all AP except the current active one.

This is iwl3945 driver from iwlwifi-git of today.
Plus I use latest -git of wpa_supplicant, and NM


Best regards,
	Maxim Levitsky

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Fri, 2009-04-10 at 23:30 +0300, Maxim Levitsky wrote:
> On Tue, 2009-04-07 at 22:37 +0200, Johannes Berg wrote:
> > On Tue, 2009-04-07 at 23:24 +0300, Maxim Levitsky wrote:
> > 
> > > First I get this in kernel logs:
> > > 
> > > 
> > > > [   29.971903] WARNING:
> > > at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79
> > > nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> > 
> > Eh, I don't think that is present in a recent wireless tree.
> 
> It is.
> 
> I have just compiled iwlwifi.git tree, and same message is there:


And I found out why device is always busy, when wpa supplicant tries to
scan. It is the disassociation sequence.

Does kernel notify, when disassociation have finished?
Maybe it is still better not to fail scan request, but block?

Best regards,
	Maxim Levitsky

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Fri, 2009-04-10 at 23:47 +0300, Maxim Levitsky wrote:

> And I found out why device is always busy, when wpa supplicant tries to
> scan. It is the disassociation sequence.
> 
> Does kernel notify, when disassociation have finished?
> Maybe it is still better not to fail scan request, but block?

Can you _please_ be more explicit? What _is_ with the association
sequence? I already _know_ that setting a random ESSID will block scans,
and no, I don't think blocking is a good idea, and no, there's nothing
to do about it.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Fri, 2009-04-10 at 23:30 +0300, Maxim Levitsky wrote:

> It is.
> 
> I have just compiled iwlwifi.git tree, and same message is there:
> 
> 
> 
> > [ 1666.298390] ------------[ cut here ]------------
> > [ 1666.298395] WARNING: at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79 nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> > [ 1666.298399] Hardware name: Aspire 5720     

> > [ 1666.298473] Pid: 13164, comm: wpa_supplicant Tainted: P           2.6.29-wl #19
> > [ 1666.298477] Call Trace:
> > [ 1666.298490]  [<ffffffff80241320>] warn_slowpath+0xd0/0x130
> > [ 1666.298504]  [<ffffffffa00f9ac6>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> > [ 1666.298512]  [<ffffffff802a8263>] ? __alloc_pages_internal+0xe3/0x4f0
> > [ 1666.298525]  [<ffffffffa00f965d>] nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]

Then your stacktrace is crap -- please apply the patch I just sent you.

> On top of that I need to note that NM doesn't show signal strenghts
> correctly.
> Instead it shows 100% for all AP except the current active one.

Separate thing -- don't hide it in this thread. I'll not even think
about looking at it here.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Sat, 2009-04-11 at 13:34 +0200, Johannes Berg wrote:
> On Fri, 2009-04-10 at 23:30 +0300, Maxim Levitsky wrote:
> 
> > It is.
> > 
> > I have just compiled iwlwifi.git tree, and same message is there:
> > 
> > 
> > 
> > > [ 1666.298390] ------------[ cut here ]------------
> > > [ 1666.298395] WARNING: at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79 nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> > > [ 1666.298399] Hardware name: Aspire 5720     
> 
> > > [ 1666.298473] Pid: 13164, comm: wpa_supplicant Tainted: P           2.6.29-wl #19
> > > [ 1666.298477] Call Trace:
> > > [ 1666.298490]  [<ffffffff80241320>] warn_slowpath+0xd0/0x130
> > > [ 1666.298504]  [<ffffffffa00f9ac6>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> > > [ 1666.298512]  [<ffffffff802a8263>] ? __alloc_pages_internal+0xe3/0x4f0
> > > [ 1666.298525]  [<ffffffffa00f965d>] nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]
> 
> Then your stacktrace is crap -- please apply the patch I just sent you.

You mean "[PATCH] cfg80211: convert mutex assert to macro"

With the patch:

> 
> [   59.405096] Call Trace:
> [   59.405106]  [<ffffffff80241320>] warn_slowpath+0xd0/0x130
> [   59.405117]  [<ffffffffa010ea86>] ? nl80211_get_wiphy+0x56/0xd0 [cfg80211]
> [   59.405122]  [<ffffffff802a8263>] ? __alloc_pages_internal+0xe3/0x4f0
> [   59.405128]  [<ffffffff804ade47>] ? netdev_run_todo+0x57/0x260
> [   59.405137]  [<ffffffffa010e76c>] nl80211_send_wiphy+0xa0c/0xa20 [cfg80211]
> [   59.405141]  [<ffffffff802a86ee>] ? __get_free_pages+0x1e/0x60
> [   59.405147]  [<ffffffff804a59ae>] ? __alloc_skb+0x6e/0x140
> [   59.405156]  [<ffffffffa010eaa4>] nl80211_get_wiphy+0x74/0xd0 [cfg80211]
> [   59.405161]  [<ffffffff804c5986>] genl_rcv_msg+0x1b6/0x1f0
> [   59.405166]  [<ffffffff804c57d0>] ? genl_rcv_msg+0x0/0x1f0
> [   59.405171]  [<ffffffff804c4839>] netlink_rcv_skb+0x89/0xb0
> [   59.405174]  [<ffffffff804c57b7>] genl_rcv+0x27/0x40
> [   59.405179]  [<ffffffff804c4234>] netlink_unicast+0x2c4/0x2e0
> [   59.405183]  [<ffffffff804a59ae>] ? __alloc_skb+0x6e/0x140
> [   59.405187]  [<ffffffff804c4464>] netlink_sendmsg+0x214/0x310
> [   59.405191]  [<ffffffff8049ceb7>] sock_sendmsg+0x127/0x140
> [   59.405198]  [<ffffffff80258c20>] ? autoremove_wake_function+0x0/0x40
> [   59.405204]  [<ffffffff802a1c62>] ? unlock_page+0x22/0x30
> [   59.405209]  [<ffffffff802b7349>] ? __do_fault+0x1e9/0x4a0
> [   59.405213]  [<ffffffff8049dd17>] ? move_addr_to_kernel+0x57/0x60
> [   59.405217]  [<ffffffff804a6e7c>] ? verify_iovec+0x3c/0xd0
> [   59.405221]  [<ffffffff8049d059>] sys_sendmsg+0x189/0x320
> [   59.405225]  [<ffffffff8049bf71>] ? sock_ioctl+0x81/0x270
> [   59.405229]  [<ffffffff802dfd21>] ? vfs_ioctl+0x31/0xa0
> [   59.405233]  [<ffffffff802dfe18>] ? do_vfs_ioctl+0x88/0x580
> [   59.405238]  [<ffffffff802d20c9>] ? __fput+0x169/0x1e0
> [   59.405242]  [<ffffffff802e03a9>] ? sys_ioctl+0x99/0xa0
> [   59.405246]  [<ffffffff8020c5db>] system_call_fastpath+0x16/0x1b

Same backtrace it seems.
Everything works, so I guess that this one if false alarm.

> 
> > On top of that I need to note that NM doesn't show signal strenghts
> > correctly.
> > Instead it shows 100% for all AP except the current active one.
> 
> Separate thing -- don't hide it in this thread. I'll not even think
> about looking at it here.
Ok, fine. Just note that this does seem to be kernel issue.

The wpa_supplicant constructs scan results when it uses wext,
but it just dumps what it receives over netlink to NM, when it uses
nl80211. Thus kernel doesn't send what it expects. But enough, I start a
separate thread on wpa_supplicant mailing list. They know about this
better.


Maxim Levitsky

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Johannes Berg]

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

On Sun, 2009-04-12 at 02:55 +0300, Maxim Levitsky wrote:

> > > > [ 1666.298395] WARNING: at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79 nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()

> You mean "[PATCH] cfg80211: convert mutex assert to macro"
> 
> With the patch:

I really want the line as above now :)

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Maxim Levitsky]

On Sun, 2009-04-12 at 09:06 +0200, Johannes Berg wrote:
> On Sun, 2009-04-12 at 02:55 +0300, Maxim Levitsky wrote:
> 
> > > > > [ 1666.298395] WARNING: at /home/maxim/software/kernel/linux-2.6/net/wireless/core.h:79 nl80211_send_wiphy+0x8bd/0xa20 [cfg80211]()
> 
> > You mean "[PATCH] cfg80211: convert mutex assert to macro"
> > 
> > With the patch:
> 
> I really want the line as above now :)

Hi,

I have just compiled 2.6.30-rc1 (latest -git of linus kernel tree), and
this warning is gone).

Best regards,
	Maxim Levitsky

Re: attempt to scan fails (device busy) if essid/ssid was changed recently

[Dan Williams]

On Tue, 2009-04-07 at 15:51 +0300, Maxim Levitsky wrote:
> On Tue, 2009-04-07 at 10:18 +0200, Johannes Berg wrote:
> > On Tue, 2009-04-07 at 03:00 +0300, Maxim Levitsky wrote:
> > 
> > > I noticed that always first attempt at scan fails when NM asks for scan.
> > > I also noticed that this happens with quite recent kernels (I think
> > > 2,6.28) didn't have this behavior.
> > 
> > I'm pretty sure it did.
> I am sure that on older kernel there was no -EBUSY error returned to
> userspace. It probably just stalled the client.
> 
> 
> > 
> > > Looking a bit deeper I discovered that each time NM disconnects from a
> > > networks it sets random ssid/essid to the card (using wireless
> > > extensions)
> > 
> > This forces a scan
> > 
> > > After that scan fails for some time.
> > > 
> > > as a NM free example you can run 
> > > 
> > > iwconfig wlan0 essid dummy
> > > iwlist scan
> > 
> > and then this fails with EBUSY.
> Thanks for explanation.
> Since NM has its reasons to clear essid (to prevent unwanted
> association), then what can be  done to prevent this (and still use
> wireless extensions, since nl80211 support isn't yet mature)?

Honestly I think this should be handled by the driver or wpa_supplicant.
Recent supplicant versions will already send a bogus SSID and BSSID to
the driver when a forced disconnection happens, but that's not enough to
stop some drivers like 2.6.27's iwl3945 from continually attempting
reconnection to an SSID in other cases.

The problem is that wext has no mechanism for saying "stop doing
whatever you're doing dammit and wait for me to tell you what to do
next".  I guess that would really be !IFF_UP, but of course you can't
scan then on most parts.

In the end, I'm probably going to patch the supplicant to handle this
and remove that code from NM.  It's really old code and things have
moved on since then.

Dan