Bug 489216 - NetworkManager requires ath9k reload to work.
Summary: NetworkManager requires ath9k reload to work.
Keywords:
Status: CLOSED INSUFFICIENT_DATA
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 10
Hardware: All
OS: Linux
low
high
Target Milestone: ---
Assignee: Dan Williams
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-03-08 17:48 UTC by Deb Mukherjee
Modified: 2009-11-11 01:04 UTC (History)
4 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2009-11-11 01:04:24 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
wpa_supplicant.log (71.29 KB, application/octet-stream)
2009-03-17 03:41 UTC, Deb Mukherjee
no flags Details

Description Deb Mukherjee 2009-03-08 17:48:53 UTC
Description of problem:


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 1 Deb Mukherjee 2009-03-08 18:50:36 UTC
Ooops! mistakenly pressed return after the summary line...

Description of the problem.
NM will establish connection to my WPA encrypted router at every reboot without problem, But will not reconnect back after suspend or if somehow the connection is lost. 

$ uname -a
Linux xxx 2.6.27.15-170.2.24.fc10.x86_64 #1 SMP Wed Feb 11 23:14:31 EST 2009 x86_64 x86_64 x86_64 GNU/Linux
 
$ lspci |grep Wireless
0b:00.0 Network controller: Atheros Communications Inc. AR5008 Wireless Network Adapter (rev 01)

$lsmod|grep ath9
ath9k                 256040  0 
mac80211              213872  1 ath9k

Output of $sudo NetworkManager --nodaemon  
*******************************************************************************
******************************************************************************* 
NetworkManager: <info>  starting...
-- Error received: File exists
-- Original message: type=0x14 length=56 flags=<REQUEST,ACK,ATOMIC> sequence-nr=1236536002 pid=4200291
NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():
Sucess

NetworkManager: <info>  eth0: driver is 'sky2'.
NetworkManager: <info>  Found new Ethernet device 'eth0'.
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_1b_63_92_f7_54
NetworkManager: <info>  wlan0: driver is 'ath9k'.
NetworkManager: <info>  wlan0: driver supports SSID scans (scan_capa 0x01).
NetworkManager: <info>  Found new 802.11 WiFi device 'wlan0'.
NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_1b_63_c4_ec_0f_0
NetworkManager: <info>  (eth0): device state change: 1 -> 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
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
NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready
NetworkManager: <info>  Activation (wlan0) starting connection 'Wireless connection 1'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4
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
NetworkManager: <info>  Activation (wlan0/wireless): access point 'Wireless connection 1' has security, but secrets are required.
NetworkManager: <info>  (wlan0): device state change: 5 -> 6
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (wlan0): device state change: 6 -> 4
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
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Wireless connection 1' has security, and secrets exist.  No new secrets needed.
NetworkManager: <info>  Config: added 'ssid' value 'home-deb'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK'
NetworkManager: <info>  Config: added 'psk' value '<omitted>'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected
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: link timed out.
NetworkManager: <info>  Activation (wlan0/wireless): association took too long.
NetworkManager: <info>  (wlan0): device state change: 5 -> 6
NetworkManager: <info>  Activation (wlan0/wireless): asking for new secrets
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <info>  wlan0: link timed out.
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (wlan0): device state change: 6 -> 4
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
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Wireless connection 1' has security, and secrets exist.  No new secrets needed.
NetworkManager: <info>  Config: added 'ssid' value 'home-deb'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK'
NetworkManager: <info>  Config: added 'psk' value '<omitted>'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected
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: link timed out.
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
NetworkManager: <info>  Activation (wlan0/wireless): association took too long.
NetworkManager: <info>  (wlan0): device state change: 5 -> 6
NetworkManager: <info>  Activation (wlan0/wireless): asking for new secrets
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected
NetworkManager: <WARN>  get_secrets_cb(): Couldn't get connection secrets: applet-device-wifi.c.1552 (get_secrets_dialog_response_cb): canceled.
NetworkManager: <info>  (wlan0): device state change: 6 -> 9
NetworkManager: <info>  Activation (wlan0) failed for access point (home-deb)
NetworkManager: <info>  Marking connection 'Wireless connection 1' invalid.
NetworkManager: <info>  Activation (wlan0) failed.
NetworkManager: <info>  (wlan0): device state change: 9 -> 3
NetworkManager: <info>  (wlan0): deactivating device (reason: 0).
***********************************************************************
***********************************************************************
Please Note the "wlan0: link timed out." -- this happens reproducibly, and at this point a dialogbox pops up asking for the WPA key which already contains the passphrase in Hex. Giving the passphrase again does not help matters.

What helps though is doing the following.

$sudo rmmod ath9k && sudo modprobe ath9k

at this stage there can be two outcomes 1. it connects directly or 2. it pops up the passphrase dialog box- and when I press the connect button it connects successfully.

Output of "$NetworkManager --no-daemon" after reloading the ath9k driver.
#############################################################################
 $ sudo NetworkManager --no-daemon 
NetworkManager: <info>  starting...
-- Error received: File exists
-- Original message: type=0x14 length=56 flags=<REQUEST,ACK,ATOMIC> sequence-nr=1236536665 pid=4200406
NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():
Sucess

NetworkManager: <info>  eth0: driver is 'sky2'.
NetworkManager: <info>  Found new Ethernet device 'eth0'.
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_1b_63_92_f7_54
NetworkManager: <info>  wlan0: driver is 'ath9k'.
NetworkManager: <info>  wlan0: driver supports SSID scans (scan_capa 0x01).
NetworkManager: <info>  Found new 802.11 WiFi device 'wlan0'.
NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_1b_63_c4_ec_0f
NetworkManager: <info>  (eth0): device state change: 1 -> 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
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
NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready
NetworkManager: <info>  Activation (wlan0) starting connection 'Wireless connection 1'
NetworkManager: <info>  (wlan0): device state change: 3 -> 4
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
NetworkManager: <info>  Activation (wlan0/wireless): access point 'Wireless connection 1' has security, but secrets are required.
NetworkManager: <info>  (wlan0): device state change: 5 -> 6
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (wlan0): device state change: 6 -> 4
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
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Wireless connection 1' has security, and secrets exist.  No new secrets needed.
NetworkManager: <info>  Config: added 'ssid' value 'home-deb'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK'
NetworkManager: <info>  Config: added 'psk' value '<omitted>'
NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected
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: link timed out.
NetworkManager: <info>  Activation (wlan0/wireless): association took too long.
NetworkManager: <info>  (wlan0): device state change: 5 -> 6
NetworkManager: <info>  Activation (wlan0/wireless): asking for new secrets
NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (wlan0): device state change: 6 -> 4
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
NetworkManager: <info>  Activation (wlan0/wireless): connection 'Wireless connection 1' has security, and secrets exist.  No new secrets needed.
NetworkManager: <info>  Config: added 'ssid' value 'home-deb'
NetworkManager: <info>  Config: added 'scan_ssid' value '1'
NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK'
NetworkManager: <info>  Config: added 'psk' value '<omitted>'
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 -> 4-way handshake
NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'home-deb'.
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
NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
NetworkManager: <info>  dhclient started with pid 6111
NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Internet Systems Consortium DHCP Client 4.0.0
Copyright 2004-2007 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:1b:63:c4:ec:0f
Sending on   LPF/wlan0/00:1b:63:c4:ec:0f
Sending on   Socket/fallback
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
DHCPOFFER from 192.168.0.1
DHCPREQUEST on wlan0 to 255.255.255.255 port 67
DHCPACK from 192.168.0.1
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 192.168.0.165
NetworkManager: <info>    prefix 24 (255.255.255.0)
NetworkManager: <info>    gateway 192.168.0.1
NetworkManager: <info>    nameserver '192.168.0.1'
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.0.165 -- renewal in 41920 seconds.
NetworkManager: <info>  (wlan0): device state change: 7 -> 8
NetworkManager: <info>  Policy set 'Wireless connection 1' (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.
##############################################################################
 

How reproducible:
Always.

Steps to reproduce:
1. click on nm-applet click on the wireless connection again.
2. right click on nm-applet >disable wireless then enable it again.
3. Suspend the computer and wake it up.
4. logout and log back in.

Actual result:
always pops up the WPA-Passphrase dialog box. when connect button is pressed in that box it tries to connect for some time then pops up the same dialogbox again
without ever establishing the connection.   

Expected result.
NM is able to connect to the stored WPA connection under every situation (see steps to reproduce)

Additional info:
wireless connection is established once ath9k is reloaded by issuing "rmmod ath9k" and then "modprobe ath9k" or rebooting the laptop.

Comment 2 Jessica Sterling 2009-03-08 19:04:30 UTC
This bug has been triaged.

Comment 3 Luis R. Rodriguez 2009-03-15 20:10:29 UTC
Your help in trying to narrow this issue down would be appreciated. Please have a good read here:

http://wireless.kernel.org/en/users/Documentation/Reporting_bugs

specifically the sections about distinguishing between userspace and drivers.

Best thing to do for example is to disable network manager, and pkill wpa_supplicant, and then try to connect manually. The information from that could be very useful.

Alternatively you are encouraged to try a recent ath9k driver, the one in 2.6.27 is pretty old and in newer kernels it gets a lot of enhancements including aggregation which you will need for 802.11n usage.

To get aggregation you'll need at least 2.6.29. You can also use compat-wireless for this. For details please see:

http://wireless.kernel.org/en/users/Drivers/ath9k#Getthelatestath9kdriver

Comment 4 Deb Mukherjee 2009-03-17 03:41:20 UTC
Created attachment 335475 [details]
wpa_supplicant.log

Comment 5 Luis R. Rodriguez 2009-06-01 17:37:00 UTC
Can you please try 2.6.30-rc series?

Or wireless-testing?

Comment 6 Luis R. Rodriguez 2009-06-01 18:37:55 UTC
Or compat-wireless:

http://wireless.kernel.org/en/users/Download

Comment 7 Michal Jaegermann 2009-06-07 15:21:34 UTC
I am seeing what it looks like the same issue although I cannot tell if this
is really ath9k or NetworkManager at fault.  If I will turn off and turn on
wifi, without touching anything in NM,  then consitently I get logs something
like that:
....
wlan0: No ProbeResp from current AP 00:13:10:1b:6f:68 - assume out of range
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 1
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 2
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 3
wlan0: direct probe to AP 00:13:10:1b:6f:68 timed out
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 1
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 2
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 3
wlan0: direct probe to AP 00:13:10:1b:6f:68 timed out
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 1
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 1
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 2
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 3
wlan0: direct probe to AP 00:13:10:1b:6f:68 timed out
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 1
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 1
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 2
wlan0: direct probe to AP 00:13:10:1b:6f:68 try 3
wlan0: direct probe to AP 00:13:10:1b:6f:68 timed out
wlan0: deauthenticating by local choice (reason=3)
....

OTOH if in NM I disable wireless through a checkbox and enable it back with
wireless already enabled in a hardware then I will get a connection as expected; no NM restart is necessary.

The latest try is with kernel-2.6.29.4-75.fc10 and
hal-0.5.12-15.20081027git.fc10 but it was "always" like that.

Comment 8 Luis R. Rodriguez 2009-06-16 05:18:11 UTC
So how did it go with 2.6.29.4 ?

Comment 9 Dan Williams 2009-10-30 07:21:17 UTC
Or try updating to Fedora 11, which has the 2.6.30 kernel and an even better ath9k driver...

Comment 10 Dan Williams 2009-11-11 01:04:24 UTC
Please re-open if this still isn't fixed by 2.6.29.4 or later or by Fedora 11 or Fedora 12.  Thanks!


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