Device: 08:00.0 Network controller: Intel Corporation PRO/Wireless
3945ABG [Golan] Network Connection (rev 02)
Last known good: 2.6.31
Bad: 26.31-git4
I use wicd to connect to wireless network.
Steps to reproduce:
1. Connect to the wireless network (WPA2), it takes long time (longer
than in 2.6.31)
2. Connect to another wireless network:
3. Connect fails with error:
[ 163.208063] ------------[ cut here ]------------
[ 163.208114] WARNING: at net/mac80211/scan.c:267
ieee80211_scan_completed+0x299/0x2b0 [mac80211]()
[ 163.208122] Hardware name: HP Compaq nx6310 (EY501ES#AKD)
[ 163.208127] Modules linked in: i915 drm i2c_algo_bit i2c_core sco
bnep rfcomm l2cap crc16 xt_tcpudp xt_limit xt_state iptable_filter
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
aes_i586 aes_generic cbc dm_crypt dm_snapshot dm_mirror dm_region_hash
dm_log dm_mod hp_wmi fuse sbp2 loop snd_hda_codec_si3054
snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_pcm_oss
snd_mixer_oss arc4 btusb bluetooth ecb snd_pcm snd_seq_dummy
snd_seq_oss snd_seq_midi snd_rawmidi iwl3945 snd_seq_midi_event
iwlcore pcmcia snd_seq firmware_class snd_timer b44 snd_seq_device
yenta_socket mac80211 uhci_hcd ssb rsrc_nonstatic ohci1394 intel_agp
video led_class snd ehci_hcd pcmcia_core mii agpgart backlight
soundcore rtc_cmos snd_page_alloc cfg80211 ieee1394 psmouse usbcore
rtc_core serio_raw sg output rfkill ac fan battery rtc_lib button
evdev
[ 163.208301] Pid: 3597, comm: wpa_supplicant Not tainted 2.6.31-git4
#1
[ 163.208305] Call Trace:
[ 163.208316] [<c03dd315>] ? printk+0x1d/0x20
[ 163.208333] [<f8485a69>] ? ieee80211_scan_completed+0x299/0x2b0
[mac80211]
[ 163.208341] [<c013b001>] warn_slowpath_common+0x71/0xc0
[ 163.208358] [<f8485a69>] ? ieee80211_scan_completed+0x299/0x2b0
[mac80211]
[ 163.208364] [<c013b06a>] warn_slowpath_null+0x1a/0x20
[ 163.208382] [<f8485a69>] ieee80211_scan_completed+0x299/0x2b0
[mac80211]
[ 163.208398] [<f8485ac9>] ieee80211_scan_cancel+0x49/0x80
[mac80211]
[ 163.208416] [<f848dd87>] ieee80211_stop+0x587/0x590 [mac80211]
[ 163.208422] [<c03dfb62>] ? _spin_unlock_bh+0x12/0x20
[ 163.208431] [<c0369ecb>] dev_close+0x6b/0xc0
[ 163.208436] [<c03dfb62>] ? _spin_unlock_bh+0x12/0x20
[ 163.208441] [<c036782f>] ? dev_set_rx_mode+0x2f/0x40
[ 163.208446] [<c0369766>] dev_change_flags+0x86/0x1a0
[ 163.208453] [<c03acf0a>] devinet_ioctl+0x66a/0x680
[ 163.208458] [<c036ac35>] ? dev_ioctl+0x295/0x550
[ 163.208464] [<c03adfb2>] inet_ioctl+0xa2/0xd0
[ 163.208471] [<c0358798>] sock_ioctl+0x68/0x270
[ 163.208476] [<c0358730>] ? sock_ioctl+0x0/0x270
[ 163.208483] [<c01dd24d>] vfs_ioctl+0x2d/0xa0
[ 163.208488] [<c01dd412>] do_vfs_ioctl+0x72/0x5f0
[ 163.208494] [<c035a24b>] ? sys_send+0x3b/0x40
[ 163.208500] [<c035acb8>] ? sys_socketcall+0x1d8/0x2b0
[ 163.208505] [<c01dda12>] sys_ioctl+0x82/0x90
[ 163.208511] [<c0102f04>] sysenter_do_call+0x12/0x22
[ 163.208515] ---[ end trace 4a480a90c21becfb ]---
[ 163.232845] ------------[ cut here ]------------
[ 163.232908] WARNING: at net/wireless/core.c:613
wdev_cleanup_work+0xbb/0xe0 [cfg80211]()
[ 163.232915] Hardware name: HP Compaq nx6310 (EY501ES#AKD)
[ 163.232921] Modules linked in: i915 drm i2c_algo_bit i2c_core sco
bnep rfcomm l2cap crc16 xt_tcpudp xt_limit xt_state iptable_filter
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
aes_i586 aes_generic cbc dm_crypt dm_snapshot dm_mirror dm_region_hash
dm_log dm_mod hp_wmi fuse sbp2 loop snd_hda_codec_si3054
snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_pcm_oss
snd_mixer_oss arc4 btusb bluetooth ecb snd_pcm snd_seq_dummy
snd_seq_oss snd_seq_midi snd_rawmidi iwl3945 snd_seq_midi_event
iwlcore pcmcia snd_seq firmware_class snd_timer b44 snd_seq_device
yenta_socket mac80211 uhci_hcd ssb rsrc_nonstatic ohci1394 intel_agp
video led_class snd ehci_hcd pcmcia_core mii agpgart backlight
soundcore rtc_cmos snd_page_alloc cfg80211 ieee1394 psmouse usbcore
rtc_core serio_raw sg output rfkill ac fan battery rtc_lib button
evdev
[ 163.233095] Pid: 9, comm: events/0 Tainted: G W 2.6.31-git4 #1
[ 163.233102] Call Trace:
[ 163.233117] [<c03dd315>] ? printk+0x1d/0x20
[ 163.233150] [<f85c255b>] ? wdev_cleanup_work+0xbb/0xe0 [cfg80211]
[ 163.233162] [<c013b001>] warn_slowpath_common+0x71/0xc0
[ 163.233195] [<f85c255b>] ? wdev_cleanup_work+0xbb/0xe0 [cfg80211]
[ 163.233205] [<c013b06a>] warn_slowpath_null+0x1a/0x20
[ 163.233237] [<f85c255b>] wdev_cleanup_work+0xbb/0xe0 [cfg80211]
[ 163.233249] [<c015235f>] ? prepare_to_wait+0x3f/0x70
[ 163.233259] [<c014dabe>] worker_thread+0x12e/0x1f0
[ 163.233267] [<c0136870>] ? default_wake_function+0x10/0x20
[ 163.233301] [<f85c24a0>] ? wdev_cleanup_work+0x0/0xe0 [cfg80211]
[ 163.233311] [<c0152110>] ? autoremove_wake_function+0x0/0x50
[ 163.233320] [<c014d990>] ? worker_thread+0x0/0x1f0
[ 163.233329] [<c0151db4>] kthread+0x74/0x80
[ 163.233338] [<c0151d40>] ? kthread+0x0/0x80
[ 163.233348] [<c0103a4f>] kernel_thread_helper+0x7/0x10
[ 163.233355] ---[ end trace 4a480a90c21becfc ]---
Config:
http://unixy.pl/maciek/download/kernel/2.6.31-git4/config-2.6.31-git4
Dmesg:
http://unixy.pl/maciek/download/kernel/2.6.31-git4/dmesg-2.6.31-git4.txt
Regards
--
Maciej Rutecki
http://www.maciek.unixy.pl
Hi Maciej,
On Wed, 2009-09-16 at 23:32 -0700, Maciej Rutecki wrote:
> [ 249.340094] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
> [ 249.345339] wlan0 direct probe responded
> [ 249.345347] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
> [ 249.347122] wlan0: authenticated
> [ 249.347152] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
> [ 249.349703] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431
> status=0 aid=1)
> [ 249.349711] wlan0: associated
> [ 253.411858] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
> 6)
This still appears to be the main issue here, that AP deauthenticates.
Could you run wpa_supplicant with debugging (-dddt) ? When you have
these logs, could you please open a bug report at
http://bugzilla.intellinuxwireless.org/ to enable us to track it?
Thank you
Reinette
2009/9/18 reinette chatre <[email protected]>:
> Hi Maciej,
>
> On Wed, 2009-09-16 at 23:32 -0700, Maciej Rutecki wrote:
>
>> [ 249.340094] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
>> [ 249.345339] wlan0 direct probe responded
>> [ 249.345347] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
>> [ 249.347122] wlan0: authenticated
>> [ 249.347152] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
>> [ 249.349703] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431
>> status=0 aid=1)
>> [ 249.349711] wlan0: associated
>> [ 253.411858] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
>> 6)
>
> This still appears to be the main issue here, that AP deauthenticates.
> Could you run wpa_supplicant with debugging (-dddt) ? When you have
> these logs, could you please open a bug report at
> http://bugzilla.intellinuxwireless.org/ to enable us to track it?
Sure, bug report:
http://bugzilla.intellinuxwireless.org/show_bug.cgi?id=2089
Debug information also available:
http://unixy.pl/maciek/download/kernel/2.6.31-git4/wpa_debug.txt
Regards
--
Maciej Rutecki
http://www.maciek.unixy.pl
2009/9/17 reinette chatre <[email protected]>:
[...]
>
> I think there is a potential race here. You start wpa_supplicant in
> background and then immediately request an IP. It is not guaranteed at
> this point that you are associated.
>
> Could you perform the last three steps of your script manually?
>
> Reinette
>
>
>
root@gumis:/home/maciek# INTERFACE=wlan0
root@gumis:/home/maciek# WPA_FILE=/etc/wpa_supplicant/wpa_supplicant.conf
root@gumis:/home/maciek# DRIVER=wext
root@gumis:/home/maciek# ifconfig eth0 down
root@gumis:/home/maciek# killall dhclient3
Dmesg:
[ 130.925689] b44: eth0: powering down PHY
root@gumis:/home/maciek# ifconfig $INTERFACE up
Demsg:
[ 171.563937] iwl3945 0000:08:00.0: firmware: requesting iwlwifi-3945-2.ucode
[ 171.611178] iwl3945 0000:08:00.0: loaded firmware version 15.32.2.9
[ 171.688664] Registered led device: iwl-phy0::radio
[ 171.688759] Registered led device: iwl-phy0::assoc
[ 171.688802] Registered led device: iwl-phy0::RX
[ 171.688844] Registered led device: iwl-phy0::TX
root@gumis:/home/maciek# killall wpa_supplicant &> /dev/null
(wait 5 seconds)
root@gumis:/home/maciek# wpa_supplicant -c $WPA_FILE -D $DRIVER -i $INTERFACE -B
(and wait)
Dmesg:
[ 249.340094] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 249.345339] wlan0 direct probe responded
[ 249.345347] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 249.347122] wlan0: authenticated
[ 249.347152] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 249.349703] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431
status=0 aid=1)
[ 249.349711] wlan0: associated
[ 253.411858] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 256.116488] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 256.118910] wlan0 direct probe responded
[ 256.118918] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 256.120663] wlan0: authenticated
[ 256.120694] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 256.122944] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 256.122951] wlan0: associated
[...]
[ 353.353780] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 356.070680] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 356.073112] wlan0 direct probe responded
[ 356.073121] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 356.074849] wlan0: authenticated
[ 356.074879] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 356.077160] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 356.077168] wlan0: associated
(Stop wainting)
root@gumis:/home/maciek# dhclient $INTERFACE
Internet Systems Consortium DHCP Client V3.1.2p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/
Listening on LPF/wlan0/00:13:02:c3:96:a8
Sending on LPF/wlan0/00:13:02:c3:96:a8
Sending on Socket/fallback
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
DHCPOFFER from 192.168.0.1
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 192.168.0.1
Reloading /etc/samba/smb.conf: smbd only.
bound to 192.168.0.102 -- renewal in 474672 seconds.
Dmesg:
[ 390.228036] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 392.969750] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 392.972333] wlan0 direct probe responded
[ 392.972342] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 392.974072] wlan0: authenticated
[...]
[ 425.722523] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 425.724773] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 425.724782] wlan0: associated
[ 429.231829] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 431.936205] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 431.938624] wlan0 direct probe responded
[ 431.938631] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 431.940470] wlan0: authenticated
[ 431.940502] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 431.942754] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 431.942761] wlan0: associated
root@gumis:/home/maciek# iwconfig $INTERFACE
wlan0 IEEE 802.11abg ESSID:"x"
Mode:Managed Frequency:2.457 GHz Access Point: 00:1B:11:F6:0F:28
Bit Rate=54 Mb/s Tx-Power=15 dBm
Retry long limit:7 RTS thr:off Fragment thr:off
Encryption key:off
Power Management:on
Link Quality=53/70 Signal level=-57 dBm
Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
Tx excessive retries:0 Invalid misc:0 Missed beacon:0
root@gumis:/home/maciek# ping onet.pl
PING onet.pl (213.180.146.27) 56(84) bytes of data.
64 bytes from s4.m1r2.onet.pl (213.180.146.27): icmp_seq=1 ttl=53 time=18.3 ms
64 bytes from s4.m1r2.onet.pl (213.180.146.27): icmp_seq=2 ttl=53 time=21.0 ms
^C
--- onet.pl ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 18.395/19.702/21.009/1.307 ms
===============================
Compare to 2.6.31:
root@gumis:/home/maciek# /home/maciek/bin/wifi/wifi_wpa.sh
Internet Systems Consortium DHCP Client V3.1.2p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/
Listening on LPF/wlan0/00:13:02:c3:96:a8
Sending on LPF/wlan0/00:13:02:c3:96:a8
Sending on Socket/fallback
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 192.168.0.1
Reloading /etc/samba/smb.conf: smbd only.
bound to 192.168.0.102 -- renewal in 596714 seconds.
wlan0 IEEE 802.11abg ESSID:"x"
Mode:Managed Frequency:2.457 GHz Access Point: 00:1B:11:F6:0F:28
Bit Rate=1 Mb/s Tx-Power=15 dBm
Retry long limit:7 RTS thr:off Fragment thr:off
Encryption
key:D99A-9047-D4B3-05CD-5AD4-041C-A1A1-577D-CF2C-7BC4-1F49-08F8-9802-2A2D-F5B3-0861
[2]
Power Management:off
Link Quality=50/70 Signal level=-60 dBm Noise level=-127 dBm
Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
Tx excessive retries:0 Invalid misc:0 Missed beacon:0
Demsg:
[ 92.188241] b44: eth0: powering down PHY
[ 92.191643] iwl3945 0000:08:00.0: firmware: requesting iwlwifi-3945-2.ucode
[ 92.305225] iwl3945 0000:08:00.0: loaded firmware version 15.32.2.9
[ 92.380738] Registered led device: iwl-phy0::radio
[ 92.381651] Registered led device: iwl-phy0::assoc
[ 92.381685] Registered led device: iwl-phy0::RX
[ 92.381708] Registered led device: iwl-phy0::TX
[ 98.353640] wlan0: authenticate with AP 00:1b:11:f6:0f:28
[ 98.355401] wlan0: authenticated
[ 98.355407] wlan0: associate with AP 00:1b:11:f6:0f:28
[ 98.357622] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431
status=0 aid=1)
[ 98.357630] wlan0: associated
--
Maciej Rutecki
http://www.maciek.unixy.pl
Hi Maciej,
On Wed, 2009-09-16 at 12:59 -0700, Maciej Rutecki wrote:
> Script (wifi_wpa.sh):
> #!/bin/sh
> INTERFACE=wlan0
> WPA_FILE=/etc/wpa_supplicant/wpa_supplicant.conf
> DRIVER=wext
> ifconfig eth0 down
> ifconfig $INTERFACE up
> sleep 3
> killall wpa_supplicant &> /dev/null
> wpa_supplicant -c $WPA_FILE -D $DRIVER -i $INTERFACE -B
> dhclient $INTERFACE
I think there is a potential race here. You start wpa_supplicant in
background and then immediately request an IP. It is not guaranteed at
this point that you are associated.
Could you perform the last three steps of your script manually?
Reinette
2009/9/16 reinette chatre <[email protected]>:
>
> The important information is not what you posted here, but still in the
> dmesg file you provided. In that log we see the following right before
> the warnings:
>
> [ 163.126590] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
> [ 163.130027] wlan0 direct probe responded
> [ 163.130032] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
> [ 163.131924] wlan0: authenticated
> [ 163.131952] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
> [ 163.134325] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
> [ 163.134331] wlan0: associated
> [ 163.155938] wlan0: deauthenticating by local choice (reason=3)
>
> It shows that association was successful, but something in userspace requested a disconnect.
Hmm. Yes, connect takes more time than in 2.6.31.
>
>>
>> [ 163.208063] ------------[ cut here ]------------
>> [ 163.208114] WARNING: at net/mac80211/scan.c:267
>> ieee80211_scan_completed+0x299/0x2b0 [mac80211]()
>
> I cannot get an exact line match based on the kernel information you
> provided. I assume it is the first warning in
> ieee80211_scan_completed(). This is not serious as it indicates that
> mac80211 received a "scan completed" indication when it was not
> scanning.
>
>
>> [ 163.232845] ------------[ cut here ]------------
>> [ 163.232908] WARNING: at net/wireless/core.c:613
>> wdev_cleanup_work+0xbb/0xe0 [cfg80211]()
>
> This warning has just been reported in linux-wireless also. Perhaps you
> can follow its discussion there. See
> http://thread.gmane.org/gmane.linux.kernel.wireless.general/39607
Thanks for information
--
Maciej Rutecki
http://www.maciek.unixy.pl
2009/9/16 reinette chatre <[email protected]>:
>
> You mentioned that you tried to connect to two networks. From the logs I
> can understand that the connection to the first network took a long
> time. This is also not due to the warnings you encountered (the warnings
> only showed up after you disconnected from second network). The reason
> why the connection to the first network took so long was some protocol
> exchange problems with AP. Here is the relevant information from your
> log:
>
[...]
>
> As you can see the AP keeps deauthenticating you with Reason 6. This
> means "Incorrect frame type or subtype received from unauthenticated
> station". Can you try to connect using wpa_supplicant? When you do make
> sure there is no other network managing applications (like network
> manager, wicd, or even other instances of wpa_supplicant etc) running.
>
> The connection to the second network went very fast - completed in one
> second. But a disconnection was requested locally just as fast. Do you
> perhaps have more than one network managing application running?
1. Stop wicd daemon (I don't use another application to connect to the network).
2. Connect to network "x" (with WPA)
Script (wifi_wpa.sh):
#!/bin/sh
INTERFACE=wlan0
WPA_FILE=/etc/wpa_supplicant/wpa_supplicant.conf
DRIVER=wext
ifconfig eth0 down
ifconfig $INTERFACE up
sleep 3
killall wpa_supplicant &> /dev/null
wpa_supplicant -c $WPA_FILE -D $DRIVER -i $INTERFACE -B
dhclient $INTERFACE
iwconfig $INTERFACE
File /etc/wpa_supplicant/wpa_supplicant.conf:
# WPA-PSK/TKIP
ctrl_interface=/var/run/wpa_supplicant
network={
ssid="x"
key_mgmt=WPA-PSK
proto=WPA
pairwise=TKIP
group=TKIP
psk=<data hidden>
priority=4
}
First try:
root@gumis:/home/maciek# /home/maciek/bin/wifi/wifi_wpa.sh
Internet Systems Consortium DHCP Client V3.1.2p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/
Listening on LPF/wlan0/00:13:02:c3:96:a8
Sending on LPF/wlan0/00:13:02:c3:96:a8
Sending on Socket/fallback
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 15
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 10
No DHCPOFFERS received.
Trying recorded lease 192.168.0.102
PING 192.168.0.1 (192.168.0.1) 56(84) bytes of data.
--- 192.168.0.1 ping statistics ---
1 packets transmitted, 0 received, +1 errors, 100% packet loss, time 0ms
No working leases in persistent database - sleeping.
wlan0 IEEE 802.11abg ESSID:"x"
Mode:Managed Frequency:2.457 GHz Access Point: 00:1B:11:F6:0F:28
Tx-Power=15 dBm
Retry long limit:7 RTS thr:off Fragment thr:off
Encryption key:off
Power Management:on
>From dmesg:
[ 256.945249] b44: eth0: powering down PHY
[ 256.948714] iwl3945 0000:08:00.0: firmware: requesting
iwlwifi-3945-2.ucode
[ 256.985907] iwl3945 0000:08:00.0: loaded firmware version 15.32.2.9
[ 257.060922] Registered led device: iwl-phy0::radio
[ 257.061021] Registered led device: iwl-phy0::assoc
[ 257.061070] Registered led device: iwl-phy0::RX
[ 257.061109] Registered led device: iwl-phy0::TX
[ 262.899954] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 262.902445] wlan0 direct probe responded
[ 262.902455] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 262.904278] wlan0: authenticated
[ 262.904328] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 262.906702] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431
status=0 aid=1)
[ 262.906711] wlan0: associated
[ 266.615969] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 269.342010] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 269.344434] wlan0 direct probe responded
[ 269.344441] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 269.346167] wlan0: authenticated
[ 269.346197] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 269.348470] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[...]
[ 416.396624] wlan0: associated
[ 419.907739] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 422.633775] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 422.832075] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 2)
[ 423.032068] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 3)
[ 423.034477] wlan0 direct probe responded
[ 423.034484] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 423.036229] wlan0: authenticated
[ 423.036266] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 423.038518] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 423.038524] wlan0: associated
[ 481.301801] wlan0: deauthenticating by local choice (reason=3)
Second try:
root@gumis:/home/maciek# /home/maciek/bin/wifi/wifi_wpa.sh
There is already a pid file /var/run/dhclient.pid with pid 4555
killed old client process, removed PID file
Internet Systems Consortium DHCP Client V3.1.2p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/
Listening on LPF/wlan0/00:13:02:c3:96:a8
Sending on LPF/wlan0/00:13:02:c3:96:a8
Sending on Socket/fallback
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 9
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 14
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 15
DHCPOFFER from 192.168.0.1
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 192.168.0.1
Reloading /etc/samba/smb.conf: smbd only.
bound to 192.168.0.102 -- renewal in 571812 seconds.
wlan0 IEEE 802.11abg ESSID:"x"
Mode:Managed Frequency:2.457 GHz Access Point: 00:1B:11:F6:0F:28
Bit Rate=54 Mb/s Tx-Power=15 dBm
Retry long limit:7 RTS thr:off Fragment thr:off
Encryption key:off
Power Management:on
Link Quality=68/70 Signal level=-42 dBm
Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
Tx excessive retries:0 Invalid misc:0 Missed beacon:0
Dmesg:
[ 481.460263] Registered led device: iwl-phy0::radio
[ 481.460289] Registered led device: iwl-phy0::assoc
[ 481.460375] Registered led device: iwl-phy0::RX
[ 481.460396] Registered led device: iwl-phy0::TX
[ 481.476399] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 481.478822] wlan0 direct probe responded
[ 481.478828] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 481.480750] wlan0: authenticated
[ 481.480775] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 481.483111] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431
status=0 aid=1)
[ 481.483116] wlan0: associated
[ 485.238506] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 485.361103] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 485.363480] wlan0 direct probe responded
[ 485.363487] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 485.365222] wlan0: authenticated
[ 485.365253] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 485.367505] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 485.367512] wlan0: associated
[ 489.334545] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 492.052130] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 492.054555] wlan0 direct probe responded
[ 492.054562] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 492.056507] wlan0: authenticated
[ 492.056541] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 492.058793] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 492.058800] wlan0: associated
[ 495.580873] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 498.302685] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 498.305121] wlan0 direct probe responded
[ 498.305129] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 498.306855] wlan0: authenticated
[ 498.306885] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 498.309142] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 498.309149] wlan0: associated
[ 501.520066] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason:
6)
[ 504.250066] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 504.252493] wlan0 direct probe responded
[ 504.252500] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 504.254227] wlan0: authenticated
[ 504.254256] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 504.256525] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 504.256532] wlan0: associated
[ 507.766452] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 510.518231] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 510.520682] wlan0 direct probe responded
[ 510.520689] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 510.522415] wlan0: authenticated
[ 510.522447] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 510.524699] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 510.524706] wlan0: associated
[ 514.012725] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 516.718174] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 516.720611] wlan0 direct probe responded
[ 516.720619] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 516.722346] wlan0: authenticated
[ 516.722377] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 516.724653] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 516.724660] wlan0: associated
[ 520.873494] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 523.608977] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 523.611397] wlan0 direct probe responded
[ 523.611405] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 523.613133] wlan0: authenticated
[ 523.613165] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 523.615415] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 523.615421] wlan0: associated
[ 527.011070] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 529.714994] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 529.717412] wlan0 direct probe responded
[ 529.717420] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 529.719146] wlan0: authenticated
[ 529.719176] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 529.721458] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28
(capab=0x431 status=0 aid=1)
[ 529.721465] wlan0: associated
3. Connect to network "y" (without wpa/wep/etc.)
Script:
#!/bin/sh
INTERFACE="wlan0"
ESSID="y"
killall wpa_supplicant
ifconfig $INTERFACE down
iwconfig $INTERFACE essid $ESSID
ifconfig $INTERFACE up
sleep 3
killall dhclient &> /dev/null
dhclient $INTERFACE
sleep 3
iwconfig $INTERFACE
First try:
root@gumis:/home/maciek# /home/maciek/bin/wifi/wifi_dhcp.sh
There is already a pid file /var/run/dhclient.pid with pid 4819
killed old client process, removed PID file
Internet Systems Consortium DHCP Client V3.1.2p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/
Listening on LPF/wlan0/00:13:02:c3:96:a8
Sending on LPF/wlan0/00:13:02:c3:96:a8
Sending on Socket/fallback
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPNAK from 192.168.1.1
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4
DHCPOFFER from 192.168.1.1
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 192.168.1.1
Reloading /etc/samba/smb.conf: smbd only.
bound to 192.168.1.102 -- renewal in 40350 seconds.
wlan0 IEEE 802.11abg ESSID:"y"
Mode:Managed Frequency:2.462 GHz Access Point: 00:0D:F3:0D:D1:4C
Bit Rate=54 Mb/s Tx-Power=15 dBm
Retry long limit:7 RTS thr:off Fragment thr:off
Encryption key:off
Power Management:on
Link Quality=31/70 Signal level=-79 dBm
Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
Tx excessive retries:0 Invalid misc:0 Missed beacon:0
Dmesg:
[ 1088.324243] Registered led device: iwl-phy0::radio
[ 1088.324270] Registered led device: iwl-phy0::assoc
[ 1088.324354] Registered led device: iwl-phy0::RX
[ 1088.324374] Registered led device: iwl-phy0::TX
[ 1088.339739] wlan0: direct probe to AP 00:0d:f3:0d:d1:4c (try 1)
[ 1088.343450] wlan0 direct probe responded
[ 1088.343458] wlan0: authenticate with AP 00:0d:f3:0d:d1:4c (try 1)
[ 1088.345313] wlan0: authenticated
[ 1088.345337] wlan0: associate with AP 00:0d:f3:0d:d1:4c (try 1)
[ 1088.347943] wlan0: RX AssocResp from 00:0d:f3:0d:d1:4c (capab=0x401
status=0 aid=2)
[ 1088.347948] wlan0: associated
Normally I use wicd to manage all networks. In first e-mail I connect
to "x" and - after this - connect to "y".
Network "x" is my own network. Sometimes (if is visible) I connect to
"y" - somebody create fast network without any protection... :-) Till
2.6.31 all works ok.
Note: in "x" and "y" I have the same IP (this only coincidence).
--
Maciej Rutecki
http://www.maciek.unixy.pl
Hi Maciej,
> Steps to reproduce:
> 1. Connect to the wireless network (WPA2), it takes long time (longer
> than in 2.6.31)
> 2. Connect to another wireless network:
> 3. Connect fails with error:
The important information is not what you posted here, but still in the
dmesg file you provided. In that log we see the following right before
the warnings:
[ 163.126590] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 163.130027] wlan0 direct probe responded
[ 163.130032] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 163.131924] wlan0: authenticated
[ 163.131952] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 163.134325] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
[ 163.134331] wlan0: associated
[ 163.155938] wlan0: deauthenticating by local choice (reason=3)
It shows that association was successful, but something in userspace requested a disconnect.
>
> [ 163.208063] ------------[ cut here ]------------
> [ 163.208114] WARNING: at net/mac80211/scan.c:267
> ieee80211_scan_completed+0x299/0x2b0 [mac80211]()
I cannot get an exact line match based on the kernel information you
provided. I assume it is the first warning in
ieee80211_scan_completed(). This is not serious as it indicates that
mac80211 received a "scan completed" indication when it was not
scanning.
> [ 163.232845] ------------[ cut here ]------------
> [ 163.232908] WARNING: at net/wireless/core.c:613
> wdev_cleanup_work+0xbb/0xe0 [cfg80211]()
This warning has just been reported in linux-wireless also. Perhaps you
can follow its discussion there. See
http://thread.gmane.org/gmane.linux.kernel.wireless.general/39607
Reinette
Hi Maciej,
On Wed, 2009-09-16 at 10:36 -0700, Maciej Rutecki wrote:
> 2009/9/16 reinette chatre <[email protected]>:
> >
> > The important information is not what you posted here, but still in the
> > dmesg file you provided. In that log we see the following right before
> > the warnings:
> >
> > [ 163.126590] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
> > [ 163.130027] wlan0 direct probe responded
> > [ 163.130032] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
> > [ 163.131924] wlan0: authenticated
> > [ 163.131952] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
> > [ 163.134325] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
> > [ 163.134331] wlan0: associated
> > [ 163.155938] wlan0: deauthenticating by local choice (reason=3)
> >
> > It shows that association was successful, but something in userspace requested a disconnect.
>
> Hmm. Yes, connect takes more time than in 2.6.31.
You mentioned that you tried to connect to two networks. From the logs I
can understand that the connection to the first network took a long
time. This is also not due to the warnings you encountered (the warnings
only showed up after you disconnected from second network). The reason
why the connection to the first network took so long was some protocol
exchange problems with AP. Here is the relevant information from your
log:
[ 117.741190] wlan0: deauthenticating by local choice (reason=3)
[ 117.741308] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 117.745515] wlan0 direct probe responded
[ 117.745523] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 117.747256] wlan0: authenticated
[ 117.747288] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 117.749529] wlan0: RX AssocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
[ 117.749536] wlan0: associated
[ 121.404153] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 124.123203] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 124.126121] wlan0 direct probe responded
[ 124.126129] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 124.127876] wlan0: authenticated
[ 124.127906] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 124.130164] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
[ 124.130172] wlan0: associated
[ 128.263997] wlan0: disassociated (Reason: 3)
[ 128.280067] wlan0: deauthenticating by local choice (reason=3)
[ 130.968263] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 130.970685] wlan0 direct probe responded
[ 130.970692] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 130.972497] wlan0: authenticated
[ 130.972529] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 130.974780] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
[ 130.974787] wlan0: associated
[ 134.511593] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 137.216183] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 137.218606] wlan0 direct probe responded
[ 137.218614] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 137.220520] wlan0: authenticated
[ 137.220555] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 137.222808] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
[ 137.222815] wlan0: associated
[ 140.758586] wlan0: deauthenticated from 00:1b:11:f6:0f:28 (Reason: 6)
[ 143.513364] wlan0: direct probe to AP 00:1b:11:f6:0f:28 (try 1)
[ 143.524448] wlan0 direct probe responded
[ 143.524456] wlan0: authenticate with AP 00:1b:11:f6:0f:28 (try 1)
[ 143.526207] wlan0: authenticated
[ 143.526238] wlan0: associate with AP 00:1b:11:f6:0f:28 (try 1)
[ 143.540625] wlan0: RX ReassocResp from 00:1b:11:f6:0f:28 (capab=0x431 status=0 aid=1)
[ 143.540632] wlan0: associated
[ 162.901260] b44: eth0: powering down PHY
[ 162.919757] wlan0: deauthenticating by local choice (reason=3)
As you can see the AP keeps deauthenticating you with Reason 6. This
means "Incorrect frame type or subtype received from unauthenticated
station". Can you try to connect using wpa_supplicant? When you do make
sure there is no other network managing applications (like network
manager, wicd, or even other instances of wpa_supplicant etc) running.
The connection to the second network went very fast - completed in one
second. But a disconnection was requested locally just as fast. Do you
perhaps have more than one network managing application running?
Reinette