Bug 523460 - after upgrade of kernel and other systems NetworkManager fails to connect to a wireless network (T40p Thinkpad Laptop) (retro-boot to an earlier kernel seems to work ok)
Summary: after upgrade of kernel and other systems NetworkManager fails to connect to ...
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 11
Hardware: i586
OS: Linux
low
high
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-09-15 15:34 UTC by Greg Huey
Modified: 2011-01-31 02:05 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2010-06-28 14:39:47 UTC
Type: ---


Attachments (Terms of Use)

Description Greg Huey 2009-09-15 15:34:24 UTC
Description of problem:
NetworkManager fails to connect to (via DHCP) wireless networks.

Initially I had no problem connecting to various wireless networks at home, work, etc.

For a couple of weeks the OS was being updated (kernel updates, security and non-security) as updates were being made available and then detected, but I did not reboot. After a reboot the new kernel came up. Since then I have not been able to connect to wireless networks that previously I had no trouble connecting to. I have not been able to find any log of error messages that would explain the problem. I have attempted to get a DHCP connection to these wireless networks by running dhclient manually, as described below. dhclient run like this does not get a connection either.

Version-Release number of selected component (if applicable):
NetworkManager-0.7.1-8.git20090708.fc11.i586
NetworkManager-gnome-0.7.1-8.git20090708.fc11.i586
NetworkManager-glib-0.7.1-8.git20090708.fc11.i586

uname -a
 Linux elwing.cosmology.name 2.6.30.5-43.fc11.i586 #1 SMP Thu Aug 27 21:18:54 EDT 2009 i686 i686 i386 GNU/Linux

How reproducible:
100%

Steps to Reproduce:
1. attempt to connect to a wireless network
2.
3.
  
Actual results:
Initially there is no connection to any network. When attempting to connect to a wireless network, NetworkManager - after a delay of about 30s - will report the error message "Disconnected The network connection has been disconnected". No connection is established. I note that during the connection attempt, the wlan0 frequency reported by iwconfig varies widely. Sometimes it reports the correct frequency, but often the reported frequency for the wlan0 device is a factor of 2 or more larger than that of the network I want to connect to.

Here is the result of a iwlist wlan0 scan:
          Cell 07 - Address: 00:14:95:83:39:71
                    Channel:6
                    Frequency:2.437 GHz (Channel 6)
                    Quality=52/70  Signal level=-58 dBm
                    Encryption key:off
                    ESSID:"2WIRE698"
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 6 Mb/s
                              9 Mb/s; 12 Mb/s; 18 Mb/s
                    Bit Rates:24 Mb/s; 36 Mb/s; 48 Mb/s; 54 Mb/s
                    Mode:Master
                    Extra:tsf=0000000013e75181
                    Extra: Last beacon: 8480ms ago
                    IE: Unknown: 00083257495245363938
                    IE: Unknown: 010882848B960C121824
                    IE: Unknown: 030106
                    IE: Unknown: 050400010000
                    IE: Unknown: 0706555320010B14
                    IE: Unknown: 2A0100
                    IE: Unknown: 32043048606C

Here is the results of several invocations of iwconfig wlan0:
wlan0     IEEE 802.11ab  ESSID:"2WIRE698"
          Mode:Managed  Frequency:5.665 GHz  Access Point: Not-Associated
          Tx-Power=20 dBm
          Retry min limit:7   RTS thr:off   Fragment thr:off
          Power Management:off
          Link Quality:0  Signal level:0  Noise level:0
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:0   Missed beacon:0

wlan0     IEEE 802.11ab  ESSID:"2WIRE698"
          Mode:Managed  Frequency:2.437 GHz  Access Point: Not-Associated
          Tx-Power=27 dBm
          Retry min limit:7   RTS thr:off   Fragment thr:off
          Power Management:off
          Link Quality:0  Signal level:0  Noise level:0
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:0   Missed beacon:0

wlan0     IEEE 802.11ab  ESSID:"2WIRE698"
          Mode:Managed  Frequency:5.66 GHz  Access Point: Not-Associated
          Tx-Power=20 dBm
          Retry min limit:7   RTS thr:off   Fragment thr:off
          Power Management:off
          Link Quality:0  Signal level:0  Noise level:0
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:0   Missed beacon:0



 I also attempted to manually connect via dhclient:

# dhclient -d -v wlan0
Internet Systems Consortium DHCP Client 4.1.0p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

Listening on LPF/wlan0/00:05:4e:41:14:01
Sending on   LPF/wlan0/00:05:4e:41:14:01
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 6
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 10
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 16
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 9
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
No DHCPOFFERS received.
No working leases in persistent database - sleeping.



Expected results:
NetworkManager should establish a connection and uptain a pid lease from the wireless network.

Additional info:

So, any idea why after the reboot I am unable to connect to this wireless network, whereas before I could connect just fine?

What can I do to see any more detailed info/error messages that would help narrow down the cause of the problem?

BTW - a general comment:
I've been using Fedora Core since 1. I've noticed a trend toward isolating the user from being able to see whats going on in the system. This makes debugging MUCH more difficult. It would be nice if Fedora had a global verbosity or expert setting that would cause everything to give more detailed info & explicit error messages.

Thanks,
Greg Huey

Comment 1 Greg Huey 2009-09-15 16:30:43 UTC
So, I figured out how to run NetworkManager in the foregound, with errors/info sent to stdout. Here is the result:

[root@elwing ~]# export NM_PPP_DEBUG=1
[root@elwing ~]# export NM_SERIAL_DEBUG=1
[root@elwing ~]# NetworkManager --no-daemon
NetworkManager: <info>  starting...
-- Error received: File exists
-- Original message: type=0x14 length=56 flags=<REQUEST,ACK,ATOMIC> sequence-nr=1253030317 pid=4207219
NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():
Sucess

NetworkManager: <info>  (eth0): new Ethernet device (driver: 'e1000')
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_0d_60_36_09_4f
NetworkManager: <info>  (wlan0): driver supports SSID scans (scan_capa 0x01).
NetworkManager: <info>  (wlan0): new 802.11 WiFi device (driver: 'ath5k')
NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_05_4e_41_14_01
NetworkManager: <info>  (ttyS0): ignoring due to lack of mobile broadband capabilties
NetworkManager: <info>  (ttyS1): ignoring due to lack of mobile broadband capabilties
NetworkManager: <info>  (eth0): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (eth0): bringing up device.
NetworkManager: <info>  (eth0): preparing device.
NetworkManager: <info>  (eth0): deactivating device (reason: 2).
NetworkManager: <info>  (wlan0): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (wlan0): bringing up device.
NetworkManager: <info>  (wlan0): preparing device.
NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
NetworkManager: <info>  (wlan0): device state change: 2 -> 3 (reason 0)
NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready
   .
   .
   .
NetworkManager: <info>  Activation (wlan0) starting connection 'Auto 2WIRE698'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (wlan0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto 2WIRE698' requires no security.  No secrets needed.
NetworkManager: <info>  Config: added 'ssid' value '2WIRE698'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Config: set interface ap_scan to 1
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <info>  wlan0: link timed out.
NetworkManager: <info>  Activation (wlan0/wireless): association took too long, failing activation.
NetworkManager: <info>  (wlan0): device state change: 5 -> 9 (reason 11)
NetworkManager: <info>  Activation (wlan0) failed for access point (2WIRE698)
NetworkManager: <info>  Marking connection 'Auto 2WIRE698' invalid.
NetworkManager: <info>  Activation (wlan0) failed.
NetworkManager: <info>  (wlan0): device state change: 9 -> 3 (reason 0)
NetworkManager: <info>  (wlan0): deactivating device (reason: 0).



below is from attempt #2 :

NetworkManager: <info>  Activation (wlan0) starting connection 'Auto 2WIRE698'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (wlan0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto 2WIRE698' requires no security.  No secrets needed.
NetworkManager: <info>  Config: added 'ssid' value '2WIRE698'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Config: set interface ap_scan to 1
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <info>  Activation (wlan0/wireless): association took too long, failing activation.
NetworkManager: <info>  (wlan0): device state change: 5 -> 9 (reason 11)
NetworkManager: <info>  Activation (wlan0) failed for access point (2WIRE698)
NetworkManager: <info>  Marking connection 'Auto 2WIRE698' invalid.
NetworkManager: <info>  Activation (wlan0) failed.
NetworkManager: <info>  (wlan0): device state change: 9 -> 3 (reason 0)
NetworkManager: <info>  (wlan0): deactivating device (reason: 0).





So, any idea why "association took too long" ?
It appears that NetworkManager never even got to the point of running dhclient and doing the "DHCPREQUEST on wlan0 to 255.255.255.255 port 67" stuff.

Any idea what the problem might be? (recalling that I had no trouble connecting to this wireless network before the reboot to the new kernel)

Any other diagnostics I can perform ?

Thanks,
Greg Huey

Comment 2 Greg Huey 2009-09-16 18:52:36 UTC
Some additional info:

I booted to an earlier kernel:

Linux elwing.cosmology.name 2.6.29.6-217.2.3.fc11.i586 #1 SMP Wed Jul 29 15:46:46 EDT 2009 i686 i686 i386 GNU/Linux

Now NetworkManager will connect to the wireless network, though the connection is somewhat laggy. This kernel has other problems - I'm now having problems with the hibernate - it often just locks up during a resume (also after a suspend/lid close) with the caps lock light flashing. The only thing I can do is then cut power and reboot. What does it mean when the caps lock light flashes?

Here is the NetworkManager output:

[root@elwing ~]# killall NetworkManager
[root@elwing ~]# export NM_SERIAL_DEBUG=1
[root@elwing ~]# export NM_PPP_DEBUG=1
You have new mail in /var/spool/mail/root
[root@elwing ~]# NetworkManager --no-daemon
NetworkManager: <info>  starting...
-- Error received: File exists
-- Original message: type=0x14 length=56 flags=<REQUEST,ACK,ATOMIC> sequence-nr=1253121686 pid=4202636
NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():
Sucess

NetworkManager: <info>  (eth0): new Ethernet device (driver: 'e1000')
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_0d_60_36_09_4f
NetworkManager: <info>  (wlan0): driver supports SSID scans (scan_capa 0x01).
NetworkManager: <info>  (wlan0): new 802.11 WiFi device (driver: 'ath5k')
NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_05_4e_41_14_01
NetworkManager: <info>  (ttyS0): ignoring due to lack of mobile broadband capabilties
NetworkManager: <info>  (ttyS1): ignoring due to lack of mobile broadband capabilties
NetworkManager: <info>  (eth0): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (eth0): bringing up device.
NetworkManager: <info>  (eth0): preparing device.
NetworkManager: <info>  (eth0): deactivating device (reason: 2).
NetworkManager: <info>  (wlan0): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (wlan0): bringing up device.
NetworkManager: <info>  (wlan0): preparing device.
NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
NetworkManager: <info>  (wlan0): device state change: 2 -> 3 (reason 0)
NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready
NetworkManager: <info>  Activation (wlan0) starting connection 'Auto JPLGuestInternet'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (wlan0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto JPLGuestInternet' requires no security.  No secrets needed.
NetworkManager: <info>  Config: added 'ssid' value 'JPLGuestInternet'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Config: set interface ap_scan to 1
NetworkManager: <info>  (wlan0): supplicant connection state:  inactive -> scanning
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed
NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'JPLGuestInternet'.
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (wlan0): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
Internet Systems Consortium DHCP Client 4.1.0p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

NetworkManager: <info>  dhclient started with pid 8336
Listening on LPF/wlan0/00:05:4e:41:14:01
Sending on   LPF/wlan0/00:05:4e:41:14:01
Sending on   Socket/fallback
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager: <info>  DHCP: device wlan0 state changed (null) -> preinit
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 207.151.192.2
NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> reboot
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
NetworkManager: <info>    address 207.151.194.92
NetworkManager: <info>    prefix 22 (255.255.252.0)
NetworkManager: <info>    gateway 207.151.192.1
NetworkManager: <info>    nameserver '137.78.160.19'
NetworkManager: <info>    nameserver '137.78.160.9'
NetworkManager: <info>    domain name 'vonkarman.net'
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
bound to 207.151.194.92 -- renewal in 1552 seconds.
NetworkManager: <info>  (wlan0): device state change: 7 -> 8 (reason 0)
NetworkManager: <debug> [1253121722.085314] periodic_update(): Roamed from BSSID 02:20:A6:32:D3:61 (JPLGuestInternet) to 02:20:A6:32:E8:31 (JPLGuestInternet)
NetworkManager: <info>  Policy set 'Auto JPLGuestInternet' (wlan0) as default for routing and DNS.
NetworkManager: <info>  Activation (wlan0) successful, device activated.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associated
NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed
DHCPREQUEST on wlan0 to 137.78.7.50 port 67
DHCPACK from 137.78.7.50
NetworkManager: <info>  DHCP: device wlan0 state changed reboot -> renew
NetworkManager: <info>    address 207.151.194.92
NetworkManager: <info>    prefix 22 (255.255.252.0)
NetworkManager: <info>    gateway 207.151.192.1
NetworkManager: <info>    nameserver '137.78.160.19'
NetworkManager: <info>    nameserver '137.78.160.9'
NetworkManager: <info>    domain name 'vonkarman.net'
bound to 207.151.194.92 -- renewal in 1686 seconds.
DHCPREQUEST on wlan0 to 137.78.7.50 port 67
DHCPACK from 137.78.7.50
bound to 207.151.194.92 -- renewal in 1530 seconds.
DHCPREQUEST on wlan0 to 137.78.7.50 port 67
DHCPACK from 137.78.7.50
bound to 207.151.194.92 -- renewal in 1417 seconds.


So, it seems my problem is a problem with the newer kernel.

Any further diagnostic info I can provide?

Thanks,
Greg Huey

Comment 3 Greg Huey 2009-09-17 22:31:45 UTC
I would add that retro-booting to the following kernel also seems to work ok:

Linux elwing.cosmology.name 2.6.29.6-217.2.16.fc11.i586 #1 SMP Mon Aug 24 17:01:46 EDT 2009 i686 i686 i386 GNU/Linux

NetworkManager output:

[root@elwing ~]# export NM_PPP_DEBUG=1
[root@elwing ~]# export NM_SERIAL_DEBUG=1
[root@elwing ~]# killall NetworkManager
You have new mail in /var/spool/mail/root
[root@elwing ~]# NetworkManager --no-daemon
NetworkManager: <info>  starting...
-- Error received: File exists
-- Original message: type=0x14 length=56 flags=<REQUEST,ACK,ATOMIC> sequence-nr=1253208329 pid=4197610
NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():
Sucess

NetworkManager: <info>  (eth0): new Ethernet device (driver: 'e1000')
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_0d_60_36_09_4f
NetworkManager: <info>  (wlan0): driver supports SSID scans (scan_capa 0x01).
NetworkManager: <info>  (wlan0): new 802.11 WiFi device (driver: 'ath5k')
NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_05_4e_41_14_01
NetworkManager: <info>  (ttyS0): ignoring due to lack of mobile broadband capabilties
NetworkManager: <info>  (ttyS1): ignoring due to lack of mobile broadband capabilties
NetworkManager: <info>  (eth0): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (eth0): bringing up device.
NetworkManager: <info>  (eth0): preparing device.
NetworkManager: <info>  (eth0): deactivating device (reason: 2).
NetworkManager: <info>  (wlan0): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (wlan0): bringing up device.
NetworkManager: <info>  (wlan0): preparing device.
NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
NetworkManager: <info>  (wlan0): device state change: 2 -> 3 (reason 0)
NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready
 .
 .
 .
NetworkManager: <info>  Activation (wlan0) starting connection 'Auto 2WIRE698'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (wlan0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto 2WIRE698' requires no security.  No secrets needed.
NetworkManager: <info>  Config: added 'ssid' value '2WIRE698'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Config: set interface ap_scan to 1
NetworkManager: <info>  (wlan0): supplicant connection state:  inactive -> scanning
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed
NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network '2WIRE698'.
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (wlan0): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
NetworkManager: <info>  dhclient started with pid 3334
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Internet Systems Consortium DHCP Client 4.1.0p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

NetworkManager: <info>  DHCP: device wlan0 state changed (null) -> preinit
Listening on LPF/wlan0/00:05:4e:41:14:01
Sending on   LPF/wlan0/00:05:4e:41:14:01
Sending on   Socket/fallback
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 192.168.1.254
NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> reboot
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
NetworkManager: <info>    address 192.168.1.157
NetworkManager: <info>    prefix 24 (255.255.255.0)
NetworkManager: <info>    gateway 192.168.1.254
NetworkManager: <info>    nameserver '192.168.1.254'
NetworkManager: <info>    domain name 'gateway.2wire.net'
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
bound to 192.168.1.157 -- renewal in 42917 seconds.
NetworkManager: <info>  (wlan0): device state change: 7 -> 8 (reason 0)
NetworkManager: <info>  Policy set 'Auto 2WIRE698' (wlan0) as default for routing and DNS.
NetworkManager: <info>  Activation (wlan0) successful, device activated.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.

Any further suggestions for things to try?

Thanks,
Greg

Comment 4 Niels Haase 2009-09-23 21:56:52 UTC
Thanks for filling this bug.
It looks like a kernel issue for me, can you please add the output 'lspci -nn | grep Net' to see which hardware we are using here. Also, is there anything between the NM failure lines in /var/log/messages at the same time?

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 5 Greg Huey 2009-09-28 07:14:02 UTC
Here is the output from lspci -nn

00:00.0 Host bridge [0600]: Intel Corporation 82855PM Processor to I/O Controller [8086:3340] (rev 03)
00:01.0 PCI bridge [0604]: Intel Corporation 82855PM Processor to AGP Controller [8086:3341] (rev 03)
00:1d.0 USB Controller [0c03]: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #1 [8086:24c2] (rev 01)
00:1d.1 USB Controller [0c03]: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #2 [8086:24c4] (rev 01)
00:1d.2 USB Controller [0c03]: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #3 [8086:24c7] (rev 01)
00:1d.7 USB Controller [0c03]: Intel Corporation 82801DB/DBM (ICH4/ICH4-M) USB2 EHCI Controller [8086:24cd] (rev 01)
00:1e.0 PCI bridge [0604]: Intel Corporation 82801 Mobile PCI Bridge [8086:2448] (rev 81)
00:1f.0 ISA bridge [0601]: Intel Corporation 82801DBM (ICH4-M) LPC Interface Bridge [8086:24cc] (rev 01)
00:1f.1 IDE interface [0101]: Intel Corporation 82801DBM (ICH4-M) IDE Controller [8086:24ca] (rev 01)
00:1f.3 SMBus [0c05]: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) SMBus Controller [8086:24c3] (rev 01)
00:1f.5 Multimedia audio controller [0401]: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) AC'97 Audio Controller [8086:24c5] (rev 01)
00:1f.6 Modem [0703]: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) AC'97 Modem Controller [8086:24c6] (rev 01)
01:00.0 VGA compatible controller [0300]: ATI Technologies Inc Radeon RV250 [Mobility FireGL 9000] [1002:4c66] (rev 02)
02:00.0 CardBus bridge [0607]: Texas Instruments PCI1520 PC card Cardbus Controller [104c:ac55] (rev 01)
02:00.1 CardBus bridge [0607]: Texas Instruments PCI1520 PC card Cardbus Controller [104c:ac55] (rev 01)
02:01.0 Ethernet controller [0200]: Intel Corporation 82540EP Gigabit Ethernet Controller (Mobile) [8086:101e] (rev 03)
02:02.0 Ethernet controller [0200]: Atheros Communications Inc. AR5211 802.11ab NIC [168c:0012] (rev 01)


The last line is the wireless device

The relevant lines from lsmod are:

ath5k                 117640  0
mac80211              164660  1 ath5k
cfg80211               30664  2 ath5k,mac80211

currently I'm up on kernel 
  Linux elwing.cosmology.name 2.6.29.6-217.2.3.fc11.i586 #1 SMP Wed Jul 29 15:46:46 EDT 2009 i686 i686 i386 GNU/Linux

I'm up on an older kernel because the wireless device works there - however, un-hibernating fails about 50% of the time (system locks up with the caps-lock light flashing, and one must power-cycle the machine be removing the battery & unplugging power). Anyway, when I next boot, I'll boot to the newest kernel I have installed and get the relevant lines out of the /var/log/messages

Thanks,
Greg

Comment 6 Greg Huey 2009-09-29 11:35:22 UTC
Ok, I booted to kernel 
Linux elwing.cosmology.name 2.6.30.5-43.fc11.i586 #1 SMP Thu Aug 27 21:18:54 EDT 2009 i686 i686 i386 GNU/Linux
and ran NetworkManager to see the output in /var/log/messages for the "association took too long, failing activation" error. Well, it looks like the output to /var/log/messages is the same as what is printed to the screen, which is what I've already reported. However, in any case, here it is:

Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) starting connection 'Auto 2WIRE698'
Sep 29 02:53:27 elwing NetworkManager: <info>  (wlan0): device state change: 3 -> 4 (reason 0)
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Sep 29 02:53:27 elwing NetworkManager: <info>  (wlan0): device state change: 4 -> 5 (reason 0)
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto 2WIRE698' requires no security.  No secrets needed.
Sep 29 02:53:27 elwing NetworkManager: <info>  Config: added 'ssid' value '2WIRE698'
Sep 29 02:53:27 elwing NetworkManager: <info>  Config: added 'scan_ssid' value '1'
Sep 29 02:53:27 elwing NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE'
Sep 29 02:53:27 elwing NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Sep 29 02:53:27 elwing NetworkManager: <info>  Config: set interface ap_scan to 1
Sep 29 02:53:27 elwing NetworkManager: <info>  (wlan0): supplicant connection state:  inactive -> scanning
Sep 29 02:53:36 elwing NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
Sep 29 02:53:37 elwing NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
Sep 29 02:53:50 elwing NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
Sep 29 02:53:52 elwing NetworkManager: <info>  wlan0: link timed out.
Sep 29 02:53:53 elwing NetworkManager: <info>  Activation (wlan0/wireless): association took too long, failing activation.
Sep 29 02:53:53 elwing NetworkManager: <info>  (wlan0): device state change: 5 -> 9 (reason 11)
Sep 29 02:53:53 elwing NetworkManager: <info>  Activation (wlan0) failed for access point (2WIRE698)
Sep 29 02:53:53 elwing NetworkManager: <info>  Marking connection 'Auto 2WIRE698' invalid.
Sep 29 02:53:53 elwing NetworkManager: <info>  Activation (wlan0) failed.
Sep 29 02:53:53 elwing NetworkManager: <info>  (wlan0): device state change: 9 -> 3 (reason 0)
Sep 29 02:53:53 elwing NetworkManager: <info>  (wlan0): deactivating device (reason: 0).

Comment 7 Greg Huey 2009-10-06 22:13:33 UTC
So, what leads do we has as to a cause of this problem?

Anything you want me to check/test ?

Here is another problem I've found - it might or might not be related to this bug - or it might simply be caused by the fact that I am forced to run an older kernel to get wireless connectivity: Periodically, while I'm connected to and using a wireless network - got a DHCP lease & logged into a remote box and doing work, minding my own business, NetworkManager will apparently 'roam' away from the access point to '(none) ((none))' for no apparent reason. I loose connectivity, and get a 'disconnected' message from NetworkManager. Since I have it set to auto-connect to the wireless network I'm using, it immediately reconnects - but I sometimes loose my remote login sessions (perhaps DHCP gets a different IP those times). Look below for the lines like this:

 <debug> [1254866460.320912] periodic_update(): Roamed from BSSID 02:20:A6:38:81:71 (JPLGuestInternet) to (none) ((none))

So, I'm sitting still - not moving around. Why is NetworkManager roaming? Ok, maybe due to fluctuations in which ap offers the highest signal strength - it might want to roam from one ap to another. _BUT_, why would it ever want to roam to "(none) ((none))" - that just makes no sense to me - I'm guessing its either a bug, or the effects of a bug - maybe the same bug?

Here is a portion of the output from NetworkManager:NetworkManager - I show the connect to the wireless network, but then note the error messages and the odd roaming:


NetworkManager: <info>  DHCP: device wlan0 state changed (null) -> preinit
Listening on LPF/wlan0/00:05:4e:41:14:01
Sending on   LPF/wlan0/00:05:4e:41:14:01
Sending on   Socket/fallback
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
DHCPOFFER from 207.151.192.3
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 207.151.192.3
NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
NetworkManager: <info>    address 207.151.195.100
NetworkManager: <info>    prefix 22 (255.255.252.0)
NetworkManager: <info>    gateway 207.151.192.1
NetworkManager: <info>    nameserver '137.78.160.19'
NetworkManager: <info>    nameserver '137.78.160.9'
NetworkManager: <info>    domain name 'vonkarman.net'
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
bound to 207.151.195.100 -- renewal in 1656 seconds.
NetworkManager: <info>  (wlan0): device state change: 7 -> 8 (reason 0)
NetworkManager: <debug> [1254862306.965917] periodic_update(): Roamed from BSSID 02:20:A6:32:EB:61 (JPLGuestInternet) to 02:20:A6:95:8D:51 (JPLGuestInternet)
NetworkManager: <info>  Policy set 'Auto JPLGuestInternet' (wlan0) as default for routing and DNS.
NetworkManager: <info>  Activation (wlan0) successful, device activated.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <debug> [1254862380.320533] periodic_update(): Roamed from BSSID 02:20:A6:95:8D:51 (JPLGuestInternet) to (none) ((none))
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed
NetworkManager: <debug> [1254862392.323153] periodic_update(): Roamed from BSSID (none) ((none)) to 02:20:A6:38:81:71 (JPLGuestInternet)
DHCPREQUEST on wlan0 to 137.78.7.50 port 67
DHCPACK from 137.78.7.50
NetworkManager: <info>  DHCP: device wlan0 state changed bound -> renew
NetworkManager: <info>    address 207.151.195.100
NetworkManager: <info>    prefix 22 (255.255.252.0)
NetworkManager: <info>    gateway 207.151.192.1
NetworkManager: <info>    nameserver '137.78.160.19'
NetworkManager: <info>    nameserver '137.78.160.9'
NetworkManager: <info>    domain name 'vonkarman.net'
bound to 207.151.195.100 -- renewal in 1513 seconds.
DHCPREQUEST on wlan0 to 137.78.7.50 port 67
DHCPACK from 137.78.7.50
bound to 207.151.195.100 -- renewal in 1370 seconds.
NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <debug> [1254866460.320912] periodic_update(): Roamed from BSSID 02:20:A6:38:81:71 (JPLGuestInternet) to (none) ((none))
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> associating
NetworkManager: <info>  (wlan0): device state change: 8 -> 3 (reason 11)
NetworkManager: <info>  (wlan0): deactivating device (reason: 11).
NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 21831
-- Error received: Numerical result out of range
-- Original message: type=0x19 length=56 flags=<REQUEST,ACK> sequence-nr=1254862376 pid=4216132
NetworkManager: <WARN>  check_one_route(): (wlan0) error -34 returned from rtnl_route_del(): Sucess

NetworkManager: <info>  Activation (wlan0) starting connection 'Auto JPLGuestInternet'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (wlan0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto JPLGuestInternet' requires no security.  No secrets needed.
NetworkManager: <info>  Config: added 'ssid' value 'JPLGuestInternet'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Config: set interface ap_scan to 1
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed
NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'JPLGuestInternet'.
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (wlan0): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
Internet Systems Consortium DHCP Client 4.1.0p1
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

Listening on LPF/wlan0/00:05:4e:41:14:01
Sending on   LPF/wlan0/00:05:4e:41:14:01
Sending on   Socket/fallback
NetworkManager: <info>  dhclient started with pid 22010
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 207.151.192.3
bound to 207.151.195.100 -- renewal in 1401 seconds.
NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> reboot
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
NetworkManager: <info>    address 207.151.195.100
NetworkManager: <info>    prefix 22 (255.255.252.0)
NetworkManager: <info>    gateway 207.151.192.1
NetworkManager: <info>    nameserver '137.78.160.19'
NetworkManager: <info>    nameserver '137.78.160.9'
NetworkManager: <info>    domain name 'vonkarman.net'
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
NetworkManager: <info>  (wlan0): device state change: 7 -> 8 (reason 0)
NetworkManager: <debug> [1254866482.142931] periodic_update(): Roamed from BSSID 02:20:A6:32:F4:01 (JPLGuestInternet) to 02:20:A6:95:8D:51 (JPLGuestInternet)
NetworkManager: <info>  Policy set 'Auto JPLGuestInternet' (wlan0) as default for routing and DNS.
NetworkManager: <info>  Activation (wlan0) successful, device activated.
NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.



Any idea what is going on?

Thanks,
Greg

Comment 8 Dan Williams 2009-10-06 22:34:19 UTC
NM doesn't actually roam, it's wpa_supplicant and the driver that control roaming.  What NM does do is periodically grab the AP MAC & SSID off the card and uses that to report whether the card has roamed APs or not.  When it goes to "(none)" that usually means the card isn't where we expect it to be.  That in and of itself won't cause disconnects though.

Note the:

NetworkManager: <info>  (wlan0): supplicant connection state:  associating ->
disconnected

lines; that means the driver has lost connection to the AP, attempts to reconnect, but fails.  Can you post some stuff from 'dmesg'?  They will also help diagnose why the card gets dropped from the AP.

Comment 9 Dmitry Kyzmin 2009-10-09 05:33:03 UTC
I have such bug as at Greg Huey. A conclusion dmesg at the moment of connection:

wlan0: direct probe to AP 00:18:f3:57:f5:51 try 1
wlan0: direct probe to AP 00:18:f3:57:f5:51 try 2
wlan0: direct probe to AP 00:18:f3:57:f5:51 try 3
wlan0: direct probe to AP 00:18:f3:57:f5:51 timed out
wlan0: direct probe to AP 00:18:f3:57:f5:51 try 1
wlan0: direct probe to AP 00:18:f3:57:f5:51 try 1
wlan0: direct probe to AP 00:18:f3:57:f5:51 try 2
wlan0: direct probe to AP 00:18:f3:57:f5:51 try 3
wlan0: direct probe to AP 00:18:f3:57:f5:51 timed out

tail -12 /var/log/wpa_supplicant.log
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
Authentication with 00:00:00:00:00:00 timed out.
Trying to associate with 00:18:f3:57:f5:51 (SSID='transAP' freq=2412 MHz)
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
Authentication with 00:00:00:00:00:00 timed out.
Trying to associate with 00:18:f3:57:f5:51 (SSID='transAP' freq=2412 MHz)
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
Trying to associate with 00:18:f3:57:f5:51 (SSID='transAP' freq=2412 MHz)
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
Authentication with 00:00:00:00:00:00 timed out.
Trying to associate with 00:18:f3:57:f5:51 (SSID='transAP' freq=2412 MHz)
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys

Comment 10 Dmitry Kyzmin 2009-10-09 05:35:42 UTC
uname -a
Linux myhost 2.6.30.8-64.fc11.i686.PAE #1 SMP Fri Sep 25 04:56:58 EDT 2009 i686 i686 i386 GNU/Linux

Comment 11 Greg Huey 2009-10-17 02:53:00 UTC
Hello,

Here are some lines from dmesg from around the moment that NetworkManager is disconnecting/complains about disconnection. However, since there is no timestamp on dmesg lines, its hard to be sure when a message actually gets written. In any case, is looks as if something is crashing (stack trace) - maybe wpa_supplicant? However, it appears as if the crash happens BEFORE the disconnect, because the stack trace is also in the output of a dmesg done before the disconnect. Anyway, here you go:

 .
 .
 .
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticated
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: association with AP 02:20:a6:38:81:71 timed out
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticated
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: RX ReassocResp from 02:20:a6:38:81:71 (capab=0x421 status=0 aid=1)
wlan0: associated
------------[ cut here ]------------
WARNING: at include/net/mac80211.h:1956 minstrel_get_rate+0xa0/0x4d8 [mac80211]() (Tainted: G        W )
Hardware name: 2373G1U
Modules linked in: nls_utf8 udf crc_itu_t vfat fat pata_pcmcia fuse sco bridge stp llc bnep l2cap bluetooth sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq dm_multipath uinput snd_intel8x0 snd_intel8x0m snd_ac97_codec ac97_bus arc4 ecb snd_pcm iTCO_wdt iTCO_vendor_support snd_timer video snd thinkpad_acpi hwmon i2c_i801 ppdev parport_pc e1000 ath5k yenta_socket rsrc_nonstatic mac80211 soundcore irda pcspkr cfg80211 parport snd_page_alloc output floppy crc_ccitt ata_generic pata_acpi radeon drm i2c_algo_bit i2c_core [last unloaded: scsi_wait_scan]
Pid: 1470, comm: wpa_supplicant Tainted: G        W  2.6.29.6-217.2.3.fc11.i586 #1
Call Trace:
 [<c042ebaa>] warn_slowpath+0x7c/0xa4
 [<c0421ea8>] ? __wake_up+0x37/0x40
 [<c06979f7>] ? netlink_unlock_table+0x2c/0x2f
 [<c06991b1>] ? netlink_broadcast+0x1d3/0x20f
 [<e09445c4>] minstrel_get_rate+0xa0/0x4d8 [mac80211]
 [<e0935df0>] rate_control_get_rate+0x84/0xc5 [mac80211]
 [<e093ad54>] invoke_tx_handlers+0x3a5/0x9df [mac80211]
 [<c067d9fb>] ? skb_release_data+0x92/0x96
 [<c041bb3b>] ? default_spin_lock_flags+0x8/0xd
 [<e093a706>] ? __ieee80211_tx_prepare+0x1e2/0x21a [mac80211]
 [<e093c5a4>] ieee80211_master_start_xmit+0x2a4/0x3b4 [mac80211]
 [<c0428179>] ? try_to_wake_up+0x22a/0x235
 [<c06847c1>] dev_hard_start_xmit+0x1ed/0x24c
 [<c0421ea8>] ? __wake_up+0x37/0x40
 [<c0692957>] __qdisc_run+0xcb/0x1b4
 [<c0684c4c>] dev_queue_xmit+0x340/0x440
 [<c067e34c>] ? __alloc_skb+0x59/0x106
 [<e093d808>] ieee80211_tx_skb+0x56/0x59 [mac80211]
 [<e09321a5>] ieee80211_send_deauth_disassoc+0xd0/0xd8 [mac80211]
 [<e0932275>] ieee80211_set_disassoc+0xc8/0x17b [mac80211]
 [<e0932413>] ieee80211_sta_req_auth+0x44/0x60 [mac80211]
 [<e092c9c1>] ieee80211_ioctl_siwgenie+0x50/0x5d [mac80211]
 [<c06eeb70>] ioctl_standard_call+0x1af/0x263
 [<c0682ad8>] ? dev_name_hash+0x1b/0x47
 [<c0682ad8>] ? dev_name_hash+0x1b/0x47
 [<c06eecf7>] wext_handle_ioctl+0xd3/0x15c
 [<e092c971>] ? ieee80211_ioctl_siwgenie+0x0/0x5d [mac80211]
 [<c0686332>] dev_ioctl+0x557/0x577
 [<c0678396>] ? sockfd_lookup_light+0x1b/0x48
 [<c06792ba>] ? sys_sendto+0xb4/0xc2
 [<c06780f9>] sock_ioctl+0x1d4/0x1e0
 [<c0677f25>] ? sock_ioctl+0x0/0x1e0
 [<c04aa48b>] vfs_ioctl+0x1d/0x74
 [<c04aad71>] do_vfs_ioctl+0x480/0x4ba
 [<c04651a4>] ? audit_syscall_entry+0x163/0x185
 [<c04aadf1>] sys_ioctl+0x46/0x66
 [<c0403f72>] syscall_call+0x7/0xb
---[ end trace 3103cf5518d011ee ]---
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticated
wlan0: associate with AP 02:20:a6:95:8d:51
wlan0: RX ReassocResp from 02:20:a6:95:8d:51 (capab=0x21 status=0 aid=1)
wlan0: associated
ath5k phy0: noise floor calibration timeout (5220MHz)
------------[ cut here ]------------
WARNING: at include/net/mac80211.h:1956 minstrel_get_rate+0xa0/0x4d8 [mac80211]() (Tainted: G        W )
Hardware name: 2373G1U
Modules linked in: nls_utf8 udf crc_itu_t vfat fat pata_pcmcia fuse sco bridge stp llc bnep l2cap bluetooth sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq dm_multipath uinput snd_intel8x0 snd_intel8x0m snd_ac97_codec ac97_bus arc4 ecb snd_pcm iTCO_wdt iTCO_vendor_support snd_timer video snd thinkpad_acpi hwmon i2c_i801 ppdev parport_pc e1000 ath5k yenta_socket rsrc_nonstatic mac80211 soundcore irda pcspkr cfg80211 parport snd_page_alloc output floppy crc_ccitt ata_generic pata_acpi radeon drm i2c_algo_bit i2c_core [last unloaded: scsi_wait_scan]
Pid: 1470, comm: wpa_supplicant Tainted: G        W  2.6.29.6-217.2.3.fc11.i586 #1
Call Trace:
 [<c042ebaa>] warn_slowpath+0x7c/0xa4
 [<c0421ea8>] ? __wake_up+0x37/0x40
 [<c06979f7>] ? netlink_unlock_table+0x2c/0x2f
 [<c06991b1>] ? netlink_broadcast+0x1d3/0x20f
 [<e09445c4>] minstrel_get_rate+0xa0/0x4d8 [mac80211]
 [<e0935df0>] rate_control_get_rate+0x84/0xc5 [mac80211]
 [<e093ad54>] invoke_tx_handlers+0x3a5/0x9df [mac80211]
 [<c067d9fb>] ? skb_release_data+0x92/0x96
 [<c041bb3b>] ? default_spin_lock_flags+0x8/0xd
 [<e093a706>] ? __ieee80211_tx_prepare+0x1e2/0x21a [mac80211]
 [<e093c5a4>] ieee80211_master_start_xmit+0x2a4/0x3b4 [mac80211]
 [<c0428179>] ? try_to_wake_up+0x22a/0x235
 [<c06847c1>] dev_hard_start_xmit+0x1ed/0x24c
 [<c0421ea8>] ? __wake_up+0x37/0x40
 [<c0692957>] __qdisc_run+0xcb/0x1b4
 [<c0684c4c>] dev_queue_xmit+0x340/0x440
 [<c067e34c>] ? __alloc_skb+0x59/0x106
 [<e093d808>] ieee80211_tx_skb+0x56/0x59 [mac80211]
 [<e09321a5>] ieee80211_send_deauth_disassoc+0xd0/0xd8 [mac80211]
 [<e0932275>] ieee80211_set_disassoc+0xc8/0x17b [mac80211]
 [<e0932413>] ieee80211_sta_req_auth+0x44/0x60 [mac80211]
 [<e092c9c1>] ieee80211_ioctl_siwgenie+0x50/0x5d [mac80211]
 [<c06eeb70>] ioctl_standard_call+0x1af/0x263
 [<c0682ad8>] ? dev_name_hash+0x1b/0x47
 [<c0682ad8>] ? dev_name_hash+0x1b/0x47
 [<c06eecf7>] wext_handle_ioctl+0xd3/0x15c
 [<e092c971>] ? ieee80211_ioctl_siwgenie+0x0/0x5d [mac80211]
 [<c0686332>] dev_ioctl+0x557/0x577
 [<c0678396>] ? sockfd_lookup_light+0x1b/0x48
 [<c06792ba>] ? sys_sendto+0xb4/0xc2
 [<c06780f9>] sock_ioctl+0x1d4/0x1e0
 [<c0677f25>] ? sock_ioctl+0x0/0x1e0
 [<c04aa48b>] vfs_ioctl+0x1d/0x74
 [<c04aad71>] do_vfs_ioctl+0x480/0x4ba
 [<c04651a4>] ? audit_syscall_entry+0x163/0x185
 [<c04aadf1>] sys_ioctl+0x46/0x66
 [<c0403f72>] syscall_call+0x7/0xb
---[ end trace 3103cf5518d011ef ]---
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticated
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: RX ReassocResp from 02:20:a6:38:81:71 (capab=0x421 status=0 aid=1)
wlan0: associated
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticated
wlan0: associate with AP 02:20:a6:95:8d:51
wlan0: RX ReassocResp from 02:20:a6:95:8d:51 (capab=0x21 status=0 aid=1)
wlan0: associated
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticated
wlan0: associate with AP 02:20:a6:95:8d:51
wlan0: RX ReassocResp from 02:20:a6:95:8d:51 (capab=0x21 status=0 aid=1)
wlan0: associated
wlan0: disassociating by local choice (reason=3)
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticated
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: deauthenticating by local choice (reason=3)
ADDRCONF(NETDEV_UP): eth0: link is not ready
ADDRCONF(NETDEV_UP): wlan0: link is not ready
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticated
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: RX AssocResp from 02:20:a6:38:81:71 (capab=0x421 status=0 aid=1)
wlan0: associated
ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
wlan0: no IPv6 routers present
ath5k phy0: noise floor calibration timeout (5820MHz)
------------[ cut here ]------------
WARNING: at include/net/mac80211.h:1956 minstrel_get_rate+0xa0/0x4d8 [mac80211]() (Tainted: G        W )
Hardware name: 2373G1U
Modules linked in: nls_utf8 udf crc_itu_t vfat fat pata_pcmcia fuse sco bridge stp llc bnep l2cap bluetooth sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq dm_multipath uinput snd_intel8x0 snd_intel8x0m snd_ac97_codec ac97_bus arc4 ecb snd_pcm iTCO_wdt iTCO_vendor_support snd_timer video snd thinkpad_acpi hwmon i2c_i801 ppdev parport_pc e1000 ath5k yenta_socket rsrc_nonstatic mac80211 soundcore irda pcspkr cfg80211 parport snd_page_alloc output floppy crc_ccitt ata_generic pata_acpi radeon drm i2c_algo_bit i2c_core [last unloaded: scsi_wait_scan]
Pid: 1470, comm: wpa_supplicant Tainted: G        W  2.6.29.6-217.2.3.fc11.i586 #1
Call Trace:
 [<c042ebaa>] warn_slowpath+0x7c/0xa4
 [<c0421ea8>] ? __wake_up+0x37/0x40
 [<c06979f7>] ? netlink_unlock_table+0x2c/0x2f
 [<c06991b1>] ? netlink_broadcast+0x1d3/0x20f
 [<e09445c4>] minstrel_get_rate+0xa0/0x4d8 [mac80211]
 [<e0935df0>] rate_control_get_rate+0x84/0xc5 [mac80211]
 [<e093ad54>] invoke_tx_handlers+0x3a5/0x9df [mac80211]
 [<c067d9fb>] ? skb_release_data+0x92/0x96
 [<c041bb3b>] ? default_spin_lock_flags+0x8/0xd
 [<e093a706>] ? __ieee80211_tx_prepare+0x1e2/0x21a [mac80211]
 [<e093c5a4>] ieee80211_master_start_xmit+0x2a4/0x3b4 [mac80211]
 [<c0428179>] ? try_to_wake_up+0x22a/0x235
 [<c06847c1>] dev_hard_start_xmit+0x1ed/0x24c
 [<c0421ea8>] ? __wake_up+0x37/0x40
 [<c0692957>] __qdisc_run+0xcb/0x1b4
 [<c0684c4c>] dev_queue_xmit+0x340/0x440
 [<c067e34c>] ? __alloc_skb+0x59/0x106
 [<e093d808>] ieee80211_tx_skb+0x56/0x59 [mac80211]
 [<e09321a5>] ieee80211_send_deauth_disassoc+0xd0/0xd8 [mac80211]
 [<e0932275>] ieee80211_set_disassoc+0xc8/0x17b [mac80211]
 [<e0932413>] ieee80211_sta_req_auth+0x44/0x60 [mac80211]
 [<e092c9c1>] ieee80211_ioctl_siwgenie+0x50/0x5d [mac80211]
 [<c06eeb70>] ioctl_standard_call+0x1af/0x263
 [<c0682ad8>] ? dev_name_hash+0x1b/0x47
 [<c0682ad8>] ? dev_name_hash+0x1b/0x47
 [<c06eecf7>] wext_handle_ioctl+0xd3/0x15c
 [<e092c971>] ? ieee80211_ioctl_siwgenie+0x0/0x5d [mac80211]
 [<c0686332>] dev_ioctl+0x557/0x577
 [<c0678396>] ? sockfd_lookup_light+0x1b/0x48
 [<c06792ba>] ? sys_sendto+0xb4/0xc2
 [<c06780f9>] sock_ioctl+0x1d4/0x1e0
 [<c0677f25>] ? sock_ioctl+0x0/0x1e0
 [<c04aa48b>] vfs_ioctl+0x1d/0x74
 [<c04aad71>] do_vfs_ioctl+0x480/0x4ba
 [<c04651a4>] ? audit_syscall_entry+0x163/0x185
 [<c04aadf1>] sys_ioctl+0x46/0x66
 [<c0403f72>] syscall_call+0x7/0xb
---[ end trace 3103cf5518d011f0 ]---
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticate with AP 02:20:a6:95:8d:51
wlan0: authenticated
wlan0: associate with AP 02:20:a6:95:8d:51
wlan0: associate with AP 02:20:a6:95:8d:51
wlan0: associate with AP 02:20:a6:95:8d:51
wlan0: association with AP 02:20:a6:95:8d:51 timed out
wlan0: direct probe to AP 02:20:a6:38:81:71 try 1
wlan0 direct probe responded
wlan0: authenticate with AP 02:20:a6:38:81:71
wlan0: authenticated
wlan0: associate with AP 02:20:a6:38:81:71
wlan0: RX ReassocResp from 02:20:a6:38:81:71 (capab=0x421 status=0 aid=1)
wlan0: associated
wlan0: disassociating by local choice (reason=3)
wlan0: direct probe to AP 02:20:a6:95:8d:51 try 1
wlan0 direct probe responded
wlan0: authenticate with AP 02:20:a6:95:8d:51

Comment 12 Greg Huey 2009-10-30 00:57:25 UTC
Please increase the priority of this bug to something above "low". It is severely impacting use of the computer that FC11 is installed on, and preventing me from being able to hibernate or suspend that machine. I'm seriously considering digging up an older linux DVD and de-grading to that.

Thanks,
Greg Huey

Comment 13 Dan Williams 2009-11-02 17:50:13 UTC
oopses mean kernel driver bugs...

John; I've had pretty good success under F11 with latest kernel and dual-band ath5k, though it sometimes does drop the connection.  Any idea what the oopses above are fixed by?

Comment 14 Greg Huey 2009-12-03 09:45:32 UTC
Hello,
Its been about a month since the last message - can someone reply to tell me what the status is of the efforts to fix these two bugs I've reported here? I know you probably only do support for Fedora in your spare time - so I don't expect bugs to get fixed immediately, but in the last month I've seen no signs any effort is being made to understand or address this problem. I'd really like to know if I should just switch to Ubuntu or one of the other linux distributions? Are you working on these bugs? Will you? Currently, as I've explained, I have to choose between an old kernel with working wifi & broken hibernate/suspend, or a new kernel with broken wifi & working hibernate/suspend. I really need to use a current kernel, but I _also need_ wifi. So, please tell me, what do you suggest I do? What would you do in my place?

Thanks,
Greg

Comment 15 Greg Huey 2009-12-03 09:45:51 UTC
Hello,
Its been about a month since the last message - can someone reply to tell me what the status is of the efforts to fix these two bugs I've reported here? I know you probably only do support for Fedora in your spare time - so I don't expect bugs to get fixed immediately, but in the last month I've seen no signs any effort is being made to understand or address this problem. I'd really like to know if I should just switch to Ubuntu or one of the other linux distributions? Are you working on these bugs? Will you? Currently, as I've explained, I have to choose between an old kernel with working wifi & broken hibernate/suspend, or a new kernel with broken wifi & working hibernate/suspend. I really need to use a current kernel, but I _also need_ wifi. So, please tell me, what do you suggest I do? What would you do in my place?

Thanks,
Greg

Comment 16 Bug Zapper 2010-04-28 10:22:48 UTC
This message is a reminder that Fedora 11 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 11.  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 '11'.

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 11'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 11 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 17 Bug Zapper 2010-06-28 14:39:47 UTC
Fedora 11 changed to end-of-life (EOL) status on 2010-06-25. Fedora 11 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.

Comment 18 Greg Huey 2011-01-31 02:05:30 UTC
Thats really excellent. I report a Fedora 11 bug in Nov 2009, while Fedora 11 is (supposedly) still be maintained. That bug report is then IGNORED until Fedora reached EOL more than 6 months later, and then you say 'oh, that version of Fedora is no longer maintained, so we can just ignore it'. So what? You did nothing but ignore it before Fedora 11 hit its EOL.

So this is your support model eh? Ignore a bug until the OS version hits EOL, then ignore it forever. Here's a shocking revelation - because of this, I switched to another version of linux. Keep this up, and you'll eventually loose all your users.

Greg Huey


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