Bug 428591 - iwl3945 disassociates from AP when dhclient runs
Summary: iwl3945 disassociates from AP when dhclient runs
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 9
Hardware: x86_64
OS: Linux
low
medium
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL: http://bughost.org/bugzilla/show_bug....
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2008-01-13 22:43 UTC by Rui Matos
Modified: 2013-01-21 20:27 UTC (History)
9 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2009-07-14 18:04:02 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
wpa log for unsuccessful attempt (37.82 KB, text/plain)
2008-01-18 14:54 UTC, Rui Matos
no flags Details
wpa log for working attempt (60.00 KB, text/plain)
2008-01-18 14:59 UTC, Rui Matos
no flags Details
Home's WEP network wpa_supplicant log (8.42 KB, text/plain)
2008-01-19 18:35 UTC, Rui Matos
no flags Details
NM's wpa_supplicant -ddd -t (22.36 KB, text/plain)
2008-02-27 16:06 UTC, Rui Matos
no flags Details
/var/log/messages corresponding to attachment 296082 (51.40 KB, text/plain)
2008-02-27 16:07 UTC, Rui Matos
no flags Details

Description Rui Matos 2008-01-13 22:43:40 UTC
I figured I should file a different bug report following my comment
https://bugzilla.redhat.com/show_bug.cgi?id=319071#c26

I've since installed kernel-2.6.23.12-101.fc8 and although what I described on
said comment is still true, I now get this warning:

Jan 12 16:30:28 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 12 16:30:30 hive kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 12 16:30:37 hive dhclient: Internet Systems Consortium DHCP Client V3.0.6-Fedora
Jan 12 16:30:37 hive dhclient: Copyright 2004-2007 Internet Systems Consortium.
Jan 12 16:30:37 hive dhclient: All rights reserved.
Jan 12 16:30:37 hive dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Jan 12 16:30:37 hive dhclient: 
Jan 12 16:30:37 hive dhclient: wmaster0: unknown hardware address type 801
Jan 12 16:30:37 hive dhclient: wmaster0: unknown hardware address type 801
Jan 12 16:30:37 hive dhclient: Listening on LPF/wlan0/00:1b:77:de:f9:26
Jan 12 16:30:37 hive dhclient: Sending on   LPF/wlan0/00:1b:77:de:f9:26
Jan 12 16:30:37 hive dhclient: Sending on   Socket/fallback
Jan 12 16:30:37 hive dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67
interval 7
Jan 12 16:30:44 hive dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67
interval 7
Jan 12 16:30:44 hive kernel: WARNING: at net/mac80211/rx.c:1663 __ieee80211_rx()
(Not tainted)
Jan 12 16:30:44 hive kernel: 
Jan 12 16:30:44 hive kernel: Call Trace:
Jan 12 16:30:44 hive kernel:  <IRQ>  [<ffffffff880e0045>]
:mac80211:__ieee80211_rx+0x3ed/0xc85
Jan 12 16:30:44 hive kernel:  [<ffffffff8816b0ea>]
:iwl3945:iwl3945_rx_reply_rx+0x7cf/0x7e1
Jan 12 16:30:44 hive kernel:  [<ffffffff880d2d48>]
:mac80211:ieee80211_tasklet_handler+0x49/0xcc
Jan 12 16:30:44 hive kernel:  [<ffffffff8103cade>] tasklet_action+0x53/0x9c
Jan 12 16:30:44 hive kernel:  [<ffffffff8103c9ed>] __do_softirq+0x55/0xc3
Jan 12 16:30:44 hive kernel:  [<ffffffff8100cd5c>] call_softirq+0x1c/0x28
Jan 12 16:30:44 hive kernel:  [<ffffffff8100de8d>] do_softirq+0x2c/0x85
Jan 12 16:30:44 hive kernel:  [<ffffffff8103c953>] irq_exit+0x3f/0x84
Jan 12 16:30:44 hive kernel:  [<ffffffff8100e149>] do_IRQ+0x13e/0x161
Jan 12 16:30:44 hive kernel:  [<ffffffff8100c0e1>] ret_from_intr+0x0/0xa
Jan 12 16:30:44 hive kernel:  <EOI>  [<ffffffff811678cf>]
acpi_idle_enter_bm+0x265/0x2d1
Jan 12 16:30:44 hive kernel:  [<ffffffff811678c5>] acpi_idle_enter_bm+0x25b/0x2d1
Jan 12 16:30:44 hive kernel:  [<ffffffff811d58e6>] cpuidle_idle_call+0x74/0xa6
Jan 12 16:30:44 hive kernel:  [<ffffffff811d5872>] cpuidle_idle_call+0x0/0xa6
Jan 12 16:30:44 hive kernel:  [<ffffffff8100ae8b>] cpu_idle+0x94/0xbc
Jan 12 16:30:44 hive kernel:  [<ffffffff81431baa>] start_kernel+0x2cf/0x2db
Jan 12 16:30:44 hive kernel:  [<ffffffff81431140>] _sinittext+0x140/0x144
Jan 12 16:30:44 hive kernel: 
Jan 12 16:30:44 hive dhclient: DHCPOFFER from 169.254.55.60
Jan 12 16:30:44 hive dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 12 16:30:44 hive dhclient: DHCPACK from 169.254.55.60
Jan 12 16:30:44 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 12 16:30:44 hive NET[3599]: /sbin/dhclient-script : updated /etc/resolv.conf
Jan 12 16:30:44 hive dhclient: bound to 10.0.2.3 -- renewal in 1369 seconds.
Jan 12 16:30:44 hive dhclient: receive_packet failed on wlan0: Network is down

The first 2 lines are the result of me starting wpa_supplicant. Then you can see
I start dhclient, the kernel prints that warning, and on the last 4 lines you
can see that the driver disassociated and got into the NO_CARRIER state.

Comment 1 John W. Linville 2008-01-14 14:58:39 UTC
FWIW, the WARNING is not actually pertinent.  It is regarding alignment of 
packet data in memory and (unless you are using an ARM, SPARC, or maybe MIPS 
CPU) it indicates at worst a minor performance problem.

I don't see any other output to indicate wha tis happening.  Did you trim the 
bottom of /var/log/messages?  Or was the "receive_packet failed" line the end?

Could you use wireshark on a different box to capture the exchange when your 
wireless card is trying to connect?

Comment 2 Rui Matos 2008-01-18 14:49:58 UTC
(In reply to comment #1)
> I don't see any other output to indicate wha tis happening.  Did you trim the 
> bottom of /var/log/messages?  Or was the "receive_packet failed" line the end?

That was all of it, see below.

> Could you use wireshark on a different box to capture the exchange when your 
> wireless card is trying to connect?

On the university network I can't. I'll see if I can reproduce this where I
control the network. For now, I'm at the univ. and I captured two wpa_supplicant
debug logs. Will attach shortly with a description.

Comment 3 Rui Matos 2008-01-18 14:54:36 UTC
Created attachment 292150 [details]
wpa log for unsuccessful attempt

This shows an unsuccessful attemp. I started wpa_supplicant and a bit later
started dhclient. Ended up with wlan0 on NO_CARRIER state and then did a
killall wpa_supplicant and killall dhclient.

Here is the /var/log/messages for that attempt:

Jan 18 14:37:51 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 18 14:37:54 hive kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

Jan 18 14:37:55 hive avahi-daemon[1826]: Registering new address record for
fe80::21b:77ff:fede:f926 o
Jan 18 14:38:42 hive dhclient: Internet Systems Consortium DHCP Client
V3.0.6-Fedora
Jan 18 14:38:42 hive dhclient: Copyright 2004-2007 Internet Systems Consortium.

Jan 18 14:38:42 hive dhclient: All rights reserved.
Jan 18 14:38:42 hive dhclient: For info, please visit
http://www.isc.org/sw/dhcp/
Jan 18 14:38:42 hive dhclient: 
Jan 18 14:38:42 hive dhclient: wmaster0: unknown hardware address type 801
Jan 18 14:38:42 hive dhclient: wmaster0: unknown hardware address type 801
Jan 18 14:38:42 hive dhclient: Listening on LPF/wlan0/00:1b:77:de:f9:26
Jan 18 14:38:42 hive dhclient: Sending on   LPF/wlan0/00:1b:77:de:f9:26
Jan 18 14:38:42 hive dhclient: Sending on   Socket/fallback
Jan 18 14:38:42 hive dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67
interval 8
Jan 18 14:38:50 hive dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67
interval 11
Jan 18 14:38:50 hive dhclient: DHCPOFFER from 172.16.255.252
Jan 18 14:38:50 hive dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 18 14:38:50 hive dhclient: DHCPACK from 172.16.255.252
Jan 18 14:38:50 hive avahi-daemon[1826]: Withdrawing address record for
fe80::21b:77ff:fede:f926 on wl
Jan 18 14:38:50 hive avahi-daemon[1826]: Joining mDNS multicast group on
interface wlan0.IPv4 with add
Jan 18 14:38:50 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 18 14:38:50 hive avahi-daemon[1826]: New relevant interface wlan0.IPv4 for
mDNS.
Jan 18 14:38:50 hive avahi-daemon[1826]: Registering new address record for
172.16.5.120 on wlan0.IPv4
Jan 18 14:38:50 hive NET[3127]: /sbin/dhclient-script : updated
/etc/resolv.conf
Jan 18 14:38:50 hive dhclient: bound to 172.16.5.120 -- renewal in 277 seconds.

Jan 18 14:38:50 hive dhclient: receive_packet failed on wlan0: Network is down

Comment 4 Rui Matos 2008-01-18 14:59:09 UTC
Created attachment 292153 [details]
wpa log for working attempt

Shortly after the previous log was captured I restarted wpa_supplicant and
saved another debug log. This time the connection was brought up successfuly
after dhclient ran.

/var/log/messages:

Jan 18 14:42:18 hive avahi-daemon[1826]: Joining mDNS multicast group on
interface wlan0.IPv4 with add
Jan 18 14:42:19 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 18 14:42:19 hive avahi-daemon[1826]: New relevant interface wlan0.IPv4 for
mDNS.
Jan 18 14:42:19 hive avahi-daemon[1826]: Registering new address record for
172.16.5.120 on wlan0.IPv4
Jan 18 14:42:21 hive kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

Jan 18 14:42:23 hive avahi-daemon[1826]: Registering new address record for
fe80::21b:77ff:fede:f926 o
Jan 18 14:43:15 hive dhclient: Internet Systems Consortium DHCP Client
V3.0.6-Fedora
Jan 18 14:43:15 hive dhclient: Copyright 2004-2007 Internet Systems Consortium.

Jan 18 14:43:15 hive dhclient: All rights reserved.
Jan 18 14:43:15 hive dhclient: For info, please visit
http://www.isc.org/sw/dhcp/
Jan 18 14:43:15 hive dhclient: 
Jan 18 14:43:15 hive dhclient: wmaster0: unknown hardware address type 801
Jan 18 14:43:15 hive dhclient: wmaster0: unknown hardware address type 801
Jan 18 14:43:15 hive dhclient: Listening on LPF/wlan0/00:1b:77:de:f9:26
Jan 18 14:43:15 hive dhclient: Sending on   LPF/wlan0/00:1b:77:de:f9:26
Jan 18 14:43:15 hive dhclient: Sending on   Socket/fallback
Jan 18 14:43:15 hive dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 18 14:43:15 hive dhclient: DHCPACK from 172.16.255.252
Jan 18 14:43:15 hive NET[3254]: /sbin/dhclient-script : updated
/etc/resolv.conf
Jan 18 14:43:15 hive dhclient: bound to 172.16.5.120 -- renewal in 20136
seconds.

Comment 5 John W. Linville 2008-01-18 15:41:53 UTC
I'm going to ask Dan Williams to take a look at those wpa_supplicant logs to 
see if he has any quick insights...

Comment 6 Dan Williams 2008-01-18 16:02:36 UTC
The failure log looks valid to me.  You'll note:

1200667097.954197: State: GROUP_HANDSHAKE -> COMPLETED

That means that the card and the AP have successfully completed all association
and authentication, and that the keys have been successfully derived and
installed to the driver/card.  It looks to me like everything on the
wpa_supplicant side is working fine until the supplicant is terminated by the
user with a signal 15.

Do the DHCP server, AP, or the RADIUS server logs show anything unusual?  Can
you run 'iwevent' during across the association and DHCP attempt to see what
messages the driver is spitting out?

Are you sure you're not running NetworkManager in the background too?  If you
want to use wpa_supplicant manually you shouldn't be running NM as well.

Note that the wireless card's link state means just about nothing, since drivers
aren't consistent here.  The _only_ thing that means anything is whether or not
'iwconfig wlan0' returns a valid BSSID.

Comment 7 John W. Linville 2008-01-18 16:20:39 UTC
Thanks, Dan!

Rui, can you provide the information requested by Dan in comment 6?

Comment 8 Rui Matos 2008-01-18 17:06:40 UTC
(In reply to comment #6)
> Do the DHCP server, AP, or the RADIUS server logs show anything unusual?

No, I don't have access to those here.

> Are you sure you're not running NetworkManager in the background too?  If you
> want to use wpa_supplicant manually you shouldn't be running NM as well.

Absolutely, killed nm-applet, did a /etc/init.d/NetworkManager stop and killed
NM's wpa_supplicant right after having started the laptop.

Now, I couldn't reproduce it yet again running wpa_supplicant and dhclient
manually. So I restarted NM and nm-applet and tried connecting (also removed the
connection data from gconf before) since usually NM can't connect at all and
here's what I got:


/var/log/messages:
Jan 18 16:47:10 hive NetworkManager: <info>  starting...
Jan 18 16:47:10 hive NetworkManager: <info>  Found radio killswitch
/org/freedesktop/Hal/devices/dell_
Jan 18 16:47:10 hive NetworkManager: <info>  eth0: Device is fully-supported
using driver 'tg3'.
Jan 18 16:47:10 hive NetworkManager: <info>  (eth0): exporting device as
/org/freedesktop/Hal/devices/
Jan 18 16:47:10 hive NetworkManager: <info>  Now managing wired Ethernet (802.3)
device 'eth0'.
Jan 18 16:47:10 hive NetworkManager: <info>  Bringing up device eth0
Jan 18 16:47:11 hive kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 18 16:47:11 hive NetworkManager: <info>  Deactivating device eth0.
Jan 18 16:47:11 hive NetworkManager: <info>  wlan0: Device is fully-supported
using driver 'iwl3945'.
Jan 18 16:47:11 hive NetworkManager: <info>  (wlan0): exporting device as
/org/freedesktop/Hal/devices
Jan 18 16:47:11 hive NetworkManager: <info>  Now managing wireless (802.11)
device 'wlan0'.
Jan 18 16:47:11 hive NetworkManager: <info>  Bringing up device wlan0
Jan 18 16:47:11 hive avahi-daemon[1826]: Joining mDNS multicast group on
interface wlan0.IPv4 with add
Jan 18 16:47:11 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 18 16:47:11 hive avahi-daemon[1826]: New relevant interface wlan0.IPv4 for mDNS.
Jan 18 16:47:11 hive avahi-daemon[1826]: Registering new address record for
172.16.5.120 on wlan0.IPv4
Jan 18 16:47:11 hive NetworkManager: <info>  Deactivating device wlan0.
Jan 18 16:47:11 hive avahi-daemon[1826]: Withdrawing address record for
172.16.5.120 on wlan0.
Jan 18 16:47:11 hive avahi-daemon[1826]: Leaving mDNS multicast group on
interface wlan0.IPv4 with add
Jan 18 16:47:11 hive avahi-daemon[1826]: Interface wlan0.IPv4 no longer relevant
for mDNS.
Jan 18 16:47:11 hive NetworkManager: <info>  (eth0) supplicant interface is now
in state 2 (from 1).
Jan 18 16:47:11 hive NetworkManager: <info>  (wlan0) supplicant interface is now
in state 2 (from 1).
Jan 18 16:47:16 hive console-kit-daemon[1735]: WARNING: Couldn't read
/proc/5461/environ: Error readin
Jan 18 16:49:43 hive NetworkManager: <info>  User request for activation of wlan0.
Jan 18 16:49:43 hive NetworkManager: <info>  Activating device wlan0
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 1 of 5
(Device Prepare) schedule
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 1 of 5
(Device Prepare) started.
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 2 of 5
(Device Configure) schedu
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 1 of 5
(Device Prepare) complete
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 2 of 5
(Device Configure) starti
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0/wireless): access
point 'Auto eduroam' 
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 2 of 5
(Device Configure) comple
Jan 18 16:49:43 hive NetworkManager: Missing or invalid key management
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 1 of 5
(Device Prepare) schedule
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 1 of 5
(Device Prepare) started.
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 2 of 5
(Device Configure) schedu
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 1 of 5
(Device Prepare) complete
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 2 of 5
(Device Configure) starti
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0/wireless):
connection 'Auto eduroam' ha
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'ssid' value 'eduroam'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'key_mgmt' value
'WPA-EAP'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'identity' value
'rui.matos'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'password' value
'<omitted>'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'eap' value 'PEAP'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'proto' value 'WPA
RSN WPA RSN'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'pairwise' value
'TKIP CCMP TKIP CCMP'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'group' value 'WEP40
WEP104 TKIP CCMP WEP40
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'fragment_size' value
'1300'
Jan 18 16:49:43 hive NetworkManager: <info>  Config: added 'phase1' value
'peapver=1'
Jan 18 16:49:43 hive NetworkManager: <info>  Activation (wlan0) Stage 2 of 5
(Device Configure) comple
Jan 18 16:49:43 hive NetworkManager: <info>  Config: set interface ap_scan to 1
Jan 18 16:49:43 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 1 -> 2
Jan 18 16:49:48 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 2 -> 3
Jan 18 16:49:48 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 3 -> 4
Jan 18 16:49:48 hive kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 18 16:49:49 hive avahi-daemon[1826]: Registering new address record for
fe80::21b:77ff:fede:f926 o
Jan 18 16:49:51 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:49:51 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 0 -> 2
Jan 18 16:49:52 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 2 -> 4
Jan 18 16:50:03 hive NetworkManager: <info>  Activation (wlan0/wireless):
disconnected during associat
Jan 18 16:50:03 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:50:03 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 0 -> 4
Jan 18 16:50:03 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:50:04 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 0 -> 4
Jan 18 16:50:04 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:50:05 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 0 -> 4
Jan 18 16:50:05 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:50:06 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 0 -> 4
Jan 18 16:50:06 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:50:07 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 0 -> 4
Jan 18 16:50:07 hive NetworkManager: <info>  (wlan0) Supplicant interface state
change: 4 -> 0
Jan 18 16:50:15 hive NetworkManager: <info>  wlan0: link timed out.


iwevent:
16:47:11.111155   wlan0    Set Mode:Managed
16:47:11.112234   wlan0    Set ESSID:off/any
16:47:11.112255   wlan0    Set Encryption key:off
16:47:33.722748   wlan0    Scan request completed
16:48:33.716013   wlan0    Scan request completed
16:49:48.268778   wlan0    Scan request completed
16:49:48.269687   wlan0    Set Mode:Managed
16:49:48.272000   wlan0    Set Frequency:2.437 GHz (Channel 6)
16:49:48.272061   wlan0    Set ESSID:"eduroam"
16:49:48.277297   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:49:48.277365   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:49:51.209175   wlan0    New Access Point/Cell address:Not-Associated
16:49:52.211365   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:49:52.211441   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:50:03.226853   wlan0    New Access Point/Cell address:Not-Associated
16:50:03.290194   wlan0    Scan request completed
16:50:03.296260   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:50:03.296280   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:50:03.296548   wlan0    New Access Point/Cell address:Not-Associated
16:50:04.302325   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:50:04.302411   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:50:04.310839   wlan0    New Access Point/Cell address:Not-Associated
16:50:05.315279   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:50:05.315340   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:50:05.320895   wlan0    New Access Point/Cell address:Not-Associated
16:50:06.324137   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:50:06.324185   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:50:06.324813   wlan0    New Access Point/Cell address:Not-Associated
16:50:07.328239   wlan0    Custom driver event:ASSOCINFO(ReqIEs=0007656475726f61
16:50:07.328285   wlan0    New Access Point/Cell address:00:0F:24:D6:A3:F0
16:50:07.328981   wlan0    New Access Point/Cell address:Not-Associated


The main point here is that, NM hardly if ever connects to this network. Using
wpa_supplicant and dhclient manually usually connects but sometimes don't (I'm
starting to think that these only fail after a reboot).


Comment 9 Rui Matos 2008-01-19 18:35:20 UTC
Created attachment 292267 [details]
Home's WEP network wpa_supplicant log

Comment 10 Rui Matos 2008-01-19 18:37:01 UTC
Could reproduce this at home with a macmini (OSX v.10.5.0) as an AP with a
104-bit WEP key. After booting, turned nm-applet, NM and wpa_supplicant off.
Then, here are all the steps on a terminal:

[jman@hive tmp]$ sudo wpa_supplicant -c/home/jman/eduroam.conf -iwlan0 -Dwext -w
-d -t 2>&1 > /tmp/wpa.log &
[1] 2714
[jman@hive tmp]$ ioctl[SIOCSIWAUTH]: Operation not supported
WEXT auth param 4 value 0x0 -
[jman@hive tmp]$
[jman@hive tmp]$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 16436 qdisc noqueue
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:1c:23:14:01:a8 brd ff:ff:ff:ff:ff:ff
3: wmaster0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc ieee80211 qlen 1000
    link/ieee802.11 00:1b:77:de:f9:26 brd ff:ff:ff:ff:ff:ff
4: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:1b:77:de:f9:26 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::21b:77ff:fede:f926/64 scope link
       valid_lft forever preferred_lft forever
[jman@hive tmp]$
[jman@hive tmp]$ sudo dhclient wlan0&
[2] 2726
[jman@hive tmp]$ Internet Systems Consortium DHCP Client V3.0.6-Fedora
Copyright 2004-2007 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/
wmaster0: unknown hardware address type 801
wmaster0: unknown hardware address type 801
Listening on LPF/wlan0/00:1b:77:de:f9:26
Sending on   LPF/wlan0/00:1b:77:de:f9:26
Sending on   Socket/fallback
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
DHCPOFFER from 10.0.2.1
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 10.0.2.1
l2_packet_receive - recvfrom: Network is down
bound to 10.0.2.3 -- renewal in 1744 seconds.

[2]+  Done                    sudo dhclient wlan0
[jman@hive tmp]$
[jman@hive tmp]$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 16436 qdisc noqueue
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:1c:23:14:01:a8 brd ff:ff:ff:ff:ff:ff
3: wmaster0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc ieee80211 qlen 1000
    link/ieee802.11 00:1b:77:de:f9:26 brd ff:ff:ff:ff:ff:ff
4: wlan0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:1b:77:de:f9:26 brd ff:ff:ff:ff:ff:ff
    inet 10.0.2.3/24 brd 10.0.2.255 scope global wlan0
[jman@hive tmp]$
[jman@hive tmp]$ ping www.ua.pt
ping: unknown host www.ua.pt
[jman@hive tmp]$

Also captured iwevent:

Waiting for Wireless Events from interfaces...
18:09:07.363527   wlan0    Set Mode:Managed
18:09:09.994176   wlan0    Scan request completed
18:09:09.994620   wlan0    Set Mode:Managed
18:09:09.996501   wlan0    Set Frequency:2.462 GHz (Channel 11)
18:09:09.996610   wlan0    Set ESSID:"dropyourweapons"
18:09:10.007133   wlan0    Custom driver
event:ASSOCINFO(ReqIEs=000f64726f70796f7572776561706f6e73010802040b160c12182432043048606cdd070050f202000100
RespIEs=010882848b0c1296182432043048606cdd180050f2020101050003a4000027a4000042435e0062322f00)
18:09:10.007202   wlan0    New Access Point/Cell address:00:16:CB:B8:21:F9

I've also attached the wpa_supplicant debug log. I should say that, on this
network, NM works fine. I just tried manually to see if it didn't work like at
the univ. and it didn't. Further manual atempts like this do work just like at
the univ. BUT NM works fine here and at univ. it doesn't.

Comment 11 Rui Matos 2008-01-19 18:40:37 UTC
And here's the macmini's /var/log/system.log:

Jan 19 18:09:11 195-23-161-252 kernel[0]: ath_newassoc:mac=00:1b:77:de:f9:26
Caplag=0x0 Flags:
Jan 19 18:09:36 195-23-161-252 bootpd[96]: can't open /etc/bootptab
Jan 19 18:09:36 195-23-161-252 bootpd[96]: server name 195-23-161-252.net.novis.pt
Jan 19 18:09:36 195-23-161-252 bootpd[96]: interface en0: ip 195.23.161.252 mask
255.255.255.255
Jan 19 18:09:36 195-23-161-252 bootpd[96]: interface en1: ip 10.0.2.1 mask
255.255.255.0
Jan 19 18:09:36 195-23-161-252 bootpd[96]: interface en1: ip 169.254.121.103
mask 255.255.0.0
Jan 19 18:09:36 195-23-161-252 bootpd[96]: dhcp: re-reading lease list
Jan 19 18:09:36 195-23-161-252 bootpd[96]: DHCP DISCOVER [en1]: 1,0:1b:77:de:f9:26
Jan 19 18:09:38: --- last message repeated 1 time ---
Jan 19 18:09:38 195-23-161-252 bootpd[96]: OFFER sent jman-PC 10.0.2.3 pktsize 300
Jan 19 18:09:38 195-23-161-252 bootpd[96]: DHCP REQUEST [en1]: 1,0:1b:77:de:f9:26
Jan 19 18:09:38 195-23-161-252 bootpd[96]: ACK sent jman-PC 10.0.2.3 pktsize 300


Comment 12 John W. Linville 2008-02-19 20:13:26 UTC
Based on comments 8 and 10 this does _not_ sound like a driver issue to me.  
If wpa_supplicant works and NM (which afaik uses wpa_suppliant behind the 
scenes) does not then this is beyond my control...?

Comment 13 Rui Matos 2008-02-19 21:05:06 UTC
(In reply to comment #12)
> Based on comments 8 and 10 this does _not_ sound like a driver issue to me.  
> If wpa_supplicant works and NM (which afaik uses wpa_suppliant behind the 
> scenes) does not then this is beyond my control...?

No. I'm sorry if I wasn't clear. In comment 10 I said that NM works just fine.
Regardless I tried to do a manual connection with wpa_supplicant and dhclient
and that did _not_ work. As far as I can see the problem is either in the
kernel, wpa_supplicant or both.


Comment 14 Rui Matos 2008-02-27 16:06:01 UTC
Created attachment 296082 [details]
NM's wpa_supplicant -ddd -t

I found out that I could add some debugging output to the iwl3945 driver so I
retried some tests now with NM on the univ's WPA2 network.

I added '-ddd -t' to the supplicant's command line on the dbus system
activation file and 'options iwl3945 debug=0x0000bc88' to /etc/modprobe.conf.
Please enlighten me if there is some other bitmask that could extract better
information from the driver preferably with less verbiage.

Comment 15 Rui Matos 2008-02-27 16:07:34 UTC
Created attachment 296083 [details]
/var/log/messages corresponding to attachment 296082 [details]

Comment 16 Rui Matos 2008-03-06 14:49:17 UTC
Some more debug info. Now with kernel 2.6.24.3-12.fc8 using only wpa_supplicant
and dhclient on the WPA univ. network.

# I connected and got IP via dhclient. Was connected for ~5 minutes.

[snip verbose driver output]

iwl3945: I iwl3945_rx_scan_results_notif Scan ch.res: 136 [802.11a] (TSF:
0x0000001B:39C66412) - 0 ela
iwl3945: I iwl3945_rx_scan_start_notif Scan start: 140 [802.11a] (TSF:
0x0000001B:39C80551) - 1 (beaco
iwl3945: I iwl3945_rx_scan_results_notif Scan ch.res: 140 [802.11a] (TSF:
0x0000001B:39C96562) - 0 ela
iwl3945: I iwl3945_rx_scan_complete_notif Scan complete: 23 channels (TSF
0x39C96CDF:0000001B) - 1
iwl3945: U iwl3945_bg_scan_completed SCAN complete scan
wlan0: RX deauthentication from 00:0f:24:d6:99:f0 (reason=2)
wlan0: deauthenticated
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 0: 00:0f:24:d6:99:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
wlan0: Initial auth_alg=0
wlan0: authenticate with AP 00:0f:24:d6:96:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
wlan0: Initial auth_alg=0
wlan0: authenticate with AP 00:0f:24:d6:96:f0
wlan0: RX authentication from 00:0f:24:d6:96:f0 (alg=0 transaction=2 status=0)
wlan0: authenticated
wlan0: associate with AP 00:0f:24:d6:96:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
wlan0: Initial auth_alg=0
wlan0: authenticate with AP 00:0f:24:d6:96:f0
wlan0: RX authentication from 00:0f:24:d6:96:f0 (alg=0 transaction=2 status=0)
wlan0: authenticated
wlan0: associate with AP 00:0f:24:d6:96:f0
wlan0: authentication frame received from 00:0f:24:d6:96:f0, but not in
authenticate state - ignored
wlan0: RX ReassocResp from 00:0f:24:d6:96:f0 (capab=0x431 status=0 aid=139)
wlan0: associated
wlan0: WMM queue=2 aci=0 acm=0 aifs=3 cWmin=15 cWmax=1023 burst=0
wlan0: WMM queue=3 aci=1 acm=0 aifs=7 cWmin=15 cWmax=1023 burst=0
wlan0: WMM queue=1 aci=2 acm=0 aifs=2 cWmin=7 cWmax=15 burst=30
wlan0: WMM queue=0 aci=3 acm=0 aifs=2 cWmin=3 cWmax=7 burst=15
wlan0: CTS protection enabled (BSSID=00:0f:24:d6:96:f0)
iwl3945: U iwl3945_bg_post_associate Associated as 139 to: 00:0f:24:d6:96:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_setup_rxon_timing beacon interval 100 beacon timer 101707
beacon tim 0
iwl3945: U iwl3945_bg_post_associate assoc id 139 beacon interval 100
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 0: 00:0f:24:d6:96:f0
wlan0: RX deauthentication from 00:0f:24:d6:96:f0 (reason=2)
wlan0: deauthenticated
wlan0: authenticate with AP 00:0f:24:d6:96:f0
wlan0: RX authentication from 00:0f:24:d6:96:f0 (alg=0 transaction=2 status=0)
wlan0: authenticated
wlan0: associate with AP 00:0f:24:d6:96:f0
iwl3945: U iwl3945_bg_post_associate Associated as 141 to: 00:0f:24:d6:96:f0
wlan0: RX ReassocResp from 00:0f:24:d6:96:f0 (capab=0x431 status=0 aid=141)
wlan0: associated
wlan0: CTS protection enabled (BSSID=00:0f:24:d6:96:f0)
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_setup_rxon_timing beacon interval 100 beacon timer 100335
beacon tim 0
iwl3945: U iwl3945_bg_post_associate assoc id 141 beacon interval 100
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 0: 00:0f:24:d6:96:f0
iwl3945: I iwl3945_rx_reply_rx Dropping (dup): 00:1b:77:de:f9:26,
00:0f:24:d6:96:f0, 00:0f:24:d6:96:f0
wlan0: invalid Michael MIC in data frame from 00:1c:bf:57:c8:16
wlan0: invalid Michael MIC in data frame from 00:0e:38:8d:80:80
wlan0: invalid Michael MIC in data frame from 00:1b:77:e6:64:af
wlan0: deauthenticate(reason=14)
wlan0: deauthenticate(reason=14)

# at this point I got disconnected. Didn't touch wpa_supplicant nor dhclient.
# After around 1 min. it connected itself again:

iwl3945: U iwl3945_bg_request_scan suspend_time 0x1000000 beacon interval 100
iwl3945: U iwl3945_bg_request_scan Initiating indirect scan.
iwl3945: U iwl3945_get_channels_for_scan Scanning 1 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 2 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 3 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 4 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 5 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 6 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 7 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 8 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 9 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Scanning 10 [ACTIVE 20]
iwl3945: U iwl3945_get_channels_for_scan Skipping current channel 11
iwl3945: U iwl3945_get_channels_for_scan Scanning 12 [PASSIVE 88]
iwl3945: U iwl3945_get_channels_for_scan Scanning 13 [PASSIVE 88]
iwl3945: U iwl3945_get_channels_for_scan total channels to scan 12 
iwl3945: I iwl3945_rx_scan_start_notif Scan start: 1 [802.11bg] (TSF:
0x0000001B:3B98EF33) - 1 (beacon
iwl3945: I iwl3945_rx_scan_results_notif Scan ch.res: 1 [802.11bg] (TSF:
0x0000001B:3B994212) - 17 ela
iwl3945: I iwl3945_rx_scan_start_notif Scan start: 2 [802.11bg] (TSF:
0x0000001B:3B9945CF) - 1 (beacon
iwl3945: I iwl3945_rx_scan_results_notif Scan ch.res: 2 [802.11bg] (TSF:
0x0000001B:3B995CD6) - 0 elap

[snip verbosity]

iwl3945: U iwl3945_bg_scan_completed SCAN complete scan
wlan0: RX deauthentication from 00:0f:24:d6:96:f0 (reason=2)
wlan0: deauthenticated
wlan0: RX deauthentication from 00:0f:24:d6:96:f0 (reason=2)
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
wlan0: Initial auth_alg=0
wlan0: authenticate with AP 00:0f:24:d6:96:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
wlan0: Initial auth_alg=0
wlan0: authenticate with AP 00:0f:24:d6:a3:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
wlan0: Initial auth_alg=0
wlan0: authenticate with AP 00:0f:24:d6:a3:f0
wlan0: RX authentication from 00:0f:24:d6:a3:f0 (alg=0 transaction=2 status=0)
wlan0: authenticated
wlan0: associate with AP 00:0f:24:d6:a3:f0
wlan0: RX ReassocResp from 00:0f:24:d6:a3:f0 (capab=0x431 status=0 aid=145)
wlan0: associated
wlan0: WMM queue=2 aci=0 acm=0 aifs=3 cWmin=15 cWmax=1023 burst=0
wlan0: WMM queue=3 aci=1 acm=0 aifs=7 cWmin=15 cWmax=1023 burst=0
wlan0: WMM queue=1 aci=2 acm=0 aifs=2 cWmin=7 cWmax=15 burst=30
wlan0: WMM queue=0 aci=3 acm=0 aifs=2 cWmin=3 cWmax=7 burst=15
wlan0: CTS protection enabled (BSSID=00:0f:24:d6:a3:f0)
iwl3945: U iwl3945_bg_post_associate Associated as 145 to: 00:0f:24:d6:a3:f0
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_setup_rxon_timing beacon interval 100 beacon timer 77735
beacon tim 0
iwl3945: U iwl3945_bg_post_associate assoc id 145 beacon interval 100
iwl3945: U iwl3945_add_station Add STA ID 24: ff:ff:ff:ff:ff:ff
iwl3945: U iwl3945_add_station Add STA ID 0: 00:0f:24:d6:a3:f0

# End

As usual NM can't even connect to this network.

Can someone forward this to an intel driver developer?


Comment 17 Rui Matos 2008-03-11 13:49:57 UTC
I filed a bug upstream:

http://bughost.org/bugzilla/show_bug.cgi?id=1629


Comment 18 Jason Haar 2008-03-13 03:57:27 UTC
I have also been affected by this bug with my Dell 430. wpa_supplicant would
associate, dhclient would start and get an address - and immediately trigger a
wlan "link not ready". I also *sometimes* get those kernel oopsies too.

However, if I leave it alone, some time within 30-60 minutes later it all comes
right and then works fine until I shut down or hibernate. (BTW hibernation
didn't appear to make the problem any worse - which is nice :-)

Anyway, I have just upgraded to 2.6.24.3-12.fc8 and wireless appears to be
reliably coming up within seconds now. Very early days yet (I've only had it up
for a few reboots), but looking good.

(I thought some positive feedback was needed on this - it was a real pain for
me. I almost had to resort to Ethernet!!! ;-)

Jason

Comment 19 Dan Williams 2008-10-20 15:23:09 UTC
back to kernel based on comment #13; is this still an issue with 2.6.26.5-28.fc8?

Comment 20 John W. Linville 2008-10-21 15:25:38 UTC
In comment 8: "NM hardly if ever connects to this network"
In comment 10: "NM works fine here and at univ. it doesn't."
In comment 13: "In comment 10 I said that NM works just fine."
In comment 16: "As usual NM can't even connect to this network."

Obviously, it is a bit unclear what the issue even is...

Regarding comment 13, NM sits on top of both wpa_supplicant and the kernel -- if they are broken then NM shouldn't work either.

What looks like to me is that we are getting disconnects shortly after otherwise successful connections.  Is this some sort of re-keying problem?  What is the encryption scheme in use?  Is the connection more stable on a network that is either open or only using plain WEP encryption?  What about WPA-PSK?

Comment 21 Rui Matos 2008-10-21 18:34:28 UTC
I'm sorry, I wasn't clear at all. I'll try to be now.

This problem occurs on different networks with different ecryption schemes.

In comment 8 and 16 I was talking about my university's network which requires this wpa_supplicant config:

network={
        ssid="------------"
        key_mgmt=WPA-EAP
        eap=PEAP
        identity="-----------"
        password="-----------"
        phase2="auth=MSCHAPV2"
}

In comment 10 I was talking about a network with these parameters:

network={
        ssid="---------------"
        key_mgmt=NONE
        wep_key0="------------"
        wep_tx_keyidx=0
        auth_alg=SHARED
}

Ok, now at this time I can't test any of those, but I can test this one:

network={
        ssid="-------------"
        psk="--------------"
}

On this last network and with versions:

kernel-2.6.26.5-45.fc9.x86_64
NetworkManager-0.7.0-0.11.svn4175.fc9.x86_64
wpa_supplicant-0.6.3-6.fc9.x86_64

I can assure you 2 things:

1. NM connects fine.
2. wpa_supplicant with above config file followed by a dhclient does NOT work.

This is what I was saying at comment 13, though now at a different network. Yes, it is weird but it's true. Here's /var/log/messages for the dhclient attempt after turning NM off (which as connected before):

Oct 21 19:12:08 hive NetworkManager: <WARN>  nm_signal_handler(): Caught signal 15, shutting down normally.
Oct 21 19:12:08 hive NetworkManager: <info>  (eth0): now unmanaged
Oct 21 19:12:08 hive NetworkManager: <info>  (eth0): device state change: 2 -> 1
Oct 21 19:12:08 hive NetworkManager: <info>  (eth0): cleaning up...
Oct 21 19:12:08 hive NetworkManager: <info>  (eth0): taking down device.
Oct 21 19:12:08 hive NetworkManager: <info>  (wlan0): now unmanaged
Oct 21 19:12:08 hive NetworkManager: <info>  (wlan0): device state change: 8 -> 1
Oct 21 19:12:08 hive NetworkManager: <info>  (wlan0): deactivating device (reason: 36).
Oct 21 19:12:09 hive NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 2610
Oct 21 19:12:09 hive NetworkManager: <WARN>  check_one_route(): (wlan0) error -34 returned from rtnl_route_del(): Missi
Oct 21 19:12:09 hive NetworkManager: <info>  (wlan0): cleaning up...
Oct 21 19:12:09 hive NetworkManager: <info>  (wlan0): taking down device.
Oct 21 19:12:09 hive kernel: ACPI: PCI interrupt for device 0000:0c:00.0 disabled
Oct 21 19:12:09 hive nm-dispatcher.action: Error in get_property: Message did not receive a reply (timeout by message b
Oct 21 19:12:48 hive kernel: ACPI: PCI Interrupt 0000:0c:00.0[A] -> GSI 17 (level, low) -> IRQ 17
Oct 21 19:12:48 hive kernel: Registered led device: iwl-phy0:radio
Oct 21 19:12:48 hive kernel: Registered led device: iwl-phy0:assoc
Oct 21 19:12:48 hive kernel: Registered led device: iwl-phy0:RX
Oct 21 19:12:48 hive kernel: Registered led device: iwl-phy0:TX
Oct 21 19:12:48 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Oct 21 19:12:54 hive dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
Oct 21 19:12:57 hive kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Oct 21 19:12:59 hive dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 14
Oct 21 19:13:00 hive dhclient: DHCPOFFER from 192.168.2.1
Oct 21 19:13:00 hive dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Oct 21 19:13:00 hive dhclient: DHCPACK from 192.168.2.1
Oct 21 19:13:00 hive kernel: ACPI: PCI interrupt for device 0000:0c:00.0 disabled
Oct 21 19:13:00 hive kernel: ACPI: PCI Interrupt 0000:0c:00.0[A] -> GSI 17 (level, low) -> IRQ 17
Oct 21 19:13:00 hive kernel: Registered led device: iwl-phy0:radio
Oct 21 19:13:00 hive kernel: Registered led device: iwl-phy0:assoc
Oct 21 19:13:00 hive kernel: Registered led device: iwl-phy0:RX
Oct 21 19:13:00 hive kernel: Registered led device: iwl-phy0:TX
Oct 21 19:13:00 hive kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Oct 21 19:13:00 hive NET[4464]: /sbin/dhclient-script : updated /etc/resolv.conf
Oct 21 19:13:00 hive dhclient: bound to 192.168.2.10 -- renewal in 11150 seconds.
Oct 21 19:13:00 hive dhclient: receive_packet failed on wlan0: Network is down

There, as you an see the driver turns the device down just after wpa_supplicant having turned it on and dhclient configured it. Here's 'ip a' output:

4: wlan0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc pfifo_fast state DOWN qlen 1000
    link/ether 00:1b:77:de:f9:26 brd ff:ff:ff:ff:ff:ff
    inet 192.168.2.10/24 brd 192.168.2.255 scope global wlan0

And here's some debugging output from wpa_supplicant:

Trying to associate with 00:18:84:27:8b:f5 (SSID='foste_ownado' freq=2412 MHz)
Associated with 00:18:84:27:8b:f5
WPA: Key negotiation completed with 00:18:84:27:8b:f5 [PTK=CCMP GTK=TKIP]
CTRL-EVENT-CONNECTED - Connection to 00:18:84:27:8b:f5 completed (auth) [id=0 id_str=]
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
Obtained 14 stack frames.
/usr/sbin/wpa_supplicant [0x44cde5]
/usr/sbin/wpa_supplicant(wpa_supplicant_disassociate+0x1c) [0x44ce7c]
/usr/sbin/wpa_supplicant(wpas_dbus_iface_remove_network+0x151) [0x43e36b]
/usr/sbin/wpa_supplicant [0x43c35f]
/lib64/libdbus-1.so.3 [0x363541c541]
/lib64/libdbus-1.so.3(dbus_connection_dispatch+0x396) [0x363540efd6]
/usr/sbin/wpa_supplicant [0x43b883]
/usr/sbin/wpa_supplicant [0x43b8f8]
/usr/sbin/wpa_supplicant [0x412945]
/usr/sbin/wpa_supplicant(eloop_run+0x26a) [0x41338d]
/usr/sbin/wpa_supplicant(wpa_supplicant_run+0x9f) [0x44f079]
/usr/sbin/wpa_supplicant(main+0x39b) [0x453601]
/lib64/libc.so.6(__libc_start_main+0xfa) [0x39a461e32a]
/usr/sbin/wpa_supplicant [0x40c769]
Obtained 14 stack frames.
/usr/sbin/wpa_supplicant [0x44cde5]
/usr/sbin/wpa_supplicant(wpa_supplicant_disassociate+0x1c) [0x44ce7c]
/usr/sbin/wpa_supplicant(wpas_dbus_iface_disconnect+0x2c) [0x43ea8c]
/usr/sbin/wpa_supplicant [0x43c3d7]
/lib64/libdbus-1.so.3 [0x363541c541]
/lib64/libdbus-1.so.3(dbus_connection_dispatch+0x396) [0x363540efd6]
/usr/sbin/wpa_supplicant [0x43b883]
/usr/sbin/wpa_supplicant [0x43b8f8]
/usr/sbin/wpa_supplicant [0x412945]
/usr/sbin/wpa_supplicant(eloop_run+0x26a) [0x41338d]
/usr/sbin/wpa_supplicant(wpa_supplicant_run+0x9f) [0x44f079]
/usr/sbin/wpa_supplicant(main+0x39b) [0x453601]
/lib64/libc.so.6(__libc_start_main+0xfa) [0x39a461e32a]
/usr/sbin/wpa_supplicant [0x40c769]
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
Obtained 14 stack frames.
/usr/sbin/wpa_supplicant [0x44cde5]
/usr/sbin/wpa_supplicant(wpa_supplicant_disassociate+0x1c) [0x44ce7c]
/usr/sbin/wpa_supplicant(wpas_dbus_iface_disconnect+0x2c) [0x43ea8c]
/usr/sbin/wpa_supplicant [0x43c3d7]
/lib64/libdbus-1.so.3 [0x363541c541]
/lib64/libdbus-1.so.3(dbus_connection_dispatch+0x396) [0x363540efd6]
/usr/sbin/wpa_supplicant [0x43b883]
/usr/sbin/wpa_supplicant [0x43b8f8]
/usr/sbin/wpa_supplicant [0x412945]
/usr/sbin/wpa_supplicant(eloop_run+0x26a) [0x41338d]
/usr/sbin/wpa_supplicant(wpa_supplicant_run+0x9f) [0x44f079]
/usr/sbin/wpa_supplicant(main+0x39b) [0x453601]
/lib64/libc.so.6(__libc_start_main+0xfa) [0x39a461e32a]
/usr/sbin/wpa_supplicant [0x40c769]
CTRL-EVENT-SCAN-RESULTS 
Obtained 14 stack frames.
/usr/sbin/wpa_supplicant [0x44cde5]
/usr/sbin/wpa_supplicant(wpa_supplicant_disassociate+0x1c) [0x44ce7c]
/usr/sbin/wpa_supplicant(wpas_dbus_iface_disconnect+0x2c) [0x43ea8c]
/usr/sbin/wpa_supplicant [0x43c3d7]
/lib64/libdbus-1.so.3 [0x363541c541]
/lib64/libdbus-1.so.3(dbus_connection_dispatch+0x396) [0x363540efd6]
/usr/sbin/wpa_supplicant [0x43b883]
/usr/sbin/wpa_supplicant [0x43b8f8]
/usr/sbin/wpa_supplicant [0x412945]
/usr/sbin/wpa_supplicant(eloop_run+0x26a) [0x41338d]
/usr/sbin/wpa_supplicant(wpa_supplicant_run+0x9f) [0x44f079]
/usr/sbin/wpa_supplicant(main+0x39b) [0x453601]
/lib64/libc.so.6(__libc_start_main+0xfa) [0x39a461e32a]
/usr/sbin/wpa_supplicant [0x40c769]

(There are some backtraces I added as a patch to the fedora package that Dan requested of me some weeks ago on IRC).

If you need anything else please ask.

Thanks for your time.

Comment 22 John W. Linville 2008-10-21 18:56:33 UTC
I'd like Dan to comment -- this seems like either a wpa_supplicant bug or just a bad wpa_supplicant.conf to me...

Comment 23 Bug Zapper 2009-06-09 23:22:27 UTC
This message is a reminder that Fedora 9 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 9.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '9'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 9's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 9 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 24 Bug Zapper 2009-07-14 18:04:02 UTC
Fedora 9 changed to end-of-life (EOL) status on 2009-07-10. Fedora 9 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.