Bug 474699

Summary: After successful connection to a WPA AP, iwlagn loses its ability to speak WEP
Product: Red Hat Enterprise Linux 5 Reporter: Zack Cerza <zcerza>
Component: kernelAssignee: John W. Linville <linville>
Status: CLOSED ERRATA QA Contact: Red Hat Kernel QE team <kernel-qe>
Severity: urgent Docs Contact:
Priority: high    
Version: 5.3CC: andriusb, dcbw, dongpo.liu, dzickus, emcnabb, jane.lv, jvillalo, keve.a.gabbert, luyu, peterm, reinette.chatre, rpacheco, shillman, walicki
Target Milestone: betaKeywords: Regression
Target Release: 5.4   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-09-02 08:27:58 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 468967    
Bug Blocks: 480792, 483701, 485920    
Attachments:
Description Flags
iwlwifi-linux-2.6.27-9to10.patch
none
iwlwifi log to kernel-2.6.18-137.el5.jwltest.80.src.rpm
none
messages to .jwltest.81.x86_64 kernel
none
wpa_supplicant.log to .jwltest.81.x86_64 kernel
none
bz474699.patch none

Description Zack Cerza 2008-12-04 21:25:10 UTC
This is a branch-off of bug #468967.

I've currently reproduced this on a Thinkpad X200 with an Intel WiFi Link 5100.

1. Use NetworkManager to connect to a WEP AP
2. Reconnect to the same AP via the same way you connected initially (i.e., no need to disconnect first)
3. If the connection succeeded, go to step 2
4. Frown

I've gotten to step 4 after as little as 4 executions of step 2.

Comment 1 Dan Williams 2008-12-04 22:19:28 UTC
See comment #96 and comment #92 from bug #468967; using this bug for that particular issue.

This seems to be related to the iwlwifi's hardware crypto capability.  Turning that off with 'swcrypto50=1' as a module parameter makes the issue disappear, so we probably have a workaround for now.

It sounds like a disagreement between the firmware and the driver/stack about when and which crypto keys are enabled.  Let me poke around a bit in iwlwifi and try to figure out what's going on here before we post the workaround and punt to 5.4 or something like that.  There may be an upstream fix we can pull back for the hwcrypto.

Comment 3 John Villalovos 2009-01-21 02:34:35 UTC
John Linville,

Any status on this?  Should we just turn off hardware crypto by default?

Comment 4 John W. Linville 2009-01-23 16:15:59 UTC
Maybe...we'll have to revisit this for 5.4 and take action appropriate to whatever driver version is shipping then.

Comment 5 RHEL Program Management 2009-02-16 15:06:57 UTC
Updating PM score.

Comment 6 DongpoLiu 2009-03-27 02:26:56 UTC
Hi, Linville:

I did some investigations on this defect in upstream kernel (linux-2.6.27.9 and linux-2.6.27.10 from kernel.org) in recent days.

after some investigation, I think the root cause of this issue comes from at least 2 aspects:
1) iwiwifi driver
2) mac80211, even ieee80211

To iwlwifi driver:
With NetworkManager, we can reproduce this issue at linux-2.6.27.9 kernel, while cannot at linux-2.6.27.10 kernel, that is we can readily switch between WEP and WPA keyed APs at linux-2.6.27.10 kernel.

I diffed the mac80211/ieee80211, there is no difference between linux-2.6.27.9
and linux-2.6.27.10. 
Attached a patch named "iwlwifi-linux-2.6.27-9to10.patch", maybe we can find iwlwifi driver root cause from this patch. 

To mac80211 even ieee80211:
I go to command line way to track this issue, see as follows:
1) ifconfig wlan0 up 
2) iwconfig wlan0 essid xxxx key restricted xxxxxx
3) dhclient wlan0.

In linux-2.6.27.9/linux-2.6.27.10 + RHEL 5.3 RC2 OS, we find 
1) iwlagn can get associated with WAP AP 
2) then temporarily get an (false?) IP address,then wlan0 interface down .

Log is as follows:
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U __iwl_poll_bit
poll_bit(0x00000020, 0x00000100, 0x00000100) - -
drivers/net/wireless/iwlwifi/iwl-4965.c 455
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U iwl4965_apm_stop_master stop
master
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U __iwl_set_bit
set_bit(0x00000020, 0x00000080) = 0x00000381
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U __iwl_set_bit
set_bit(0x00000024, 0x00000004) = 0x080033D4
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U __iwl_poll_bit
poll_bit(0x00000020, 0x00000001, 0x00000001) - -
drivers/net/wireless/iwlwifi/iwl-4965.c 501
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U __iwl_grab_nic_access
grabbing nic access - drivers/net/wireless/iwlwifi/iwl-4965.c 508
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U __iwl_release_nic_access
releasing nic access - drivers/net/wireless/iwlwifi/iwl-4965.c 521
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U iwl_clear_free_frames 0
frames on pre-allocated heap on clear.
Mar 26 18:56:32 osve-sr kernel: iwlagn 0000:04:00.0: PCI INT A disabled
Mar 26 18:56:32 osve-sr kernel: ieee80211 phy0: U iwl4965_mac_stop leave


So from above log, maybe we need update both mac80211 even ieee80211 to fix this issue ? 
the gap between 2.6.18 and 2.6.27.10 kernel is huge, and the efforts can be big.

Comment 7 DongpoLiu 2009-03-27 02:27:34 UTC
Created attachment 336937 [details]
iwlwifi-linux-2.6.27-9to10.patch

Comment 8 John W. Linville 2009-04-02 03:06:25 UTC
I have backported one of the iwlwifi patches between 2.6.27.9 and 2.6.27.10 to the test kernels here:

   http://people.redhat.com/linville/kernels/rhel5/

Please give those a try and post the results here -- thanks!

Comment 9 DongpoLiu 2009-04-02 09:09:16 UTC
I tried kernel-2.6.18-137.el5.jwltest.80.x86_64.rpm at RHEL 5.3 RC2 OS, it still fails to get associated with WEP-keyed AP.

then I rebuild kernel-2.6.18-137.el5.jwltest.80.src.rpm with iwlwifi debug enabled, after OS boots up, I run "echo 0xcff5fd9f   >  /sys/class/net/wlan0/device/debug_level", attached is its log file.

I always find:
Apr  2 16:13:33 osve-sr kernel: iwlagn 0000:04:00.0: I __iwl_read32 read_direct32(0x0000000C) - drivers/net/wireless/iwlwifi/iwl-agn.c 1601
Apr  2 16:13:33 osve-sr kernel: iwlagn 0000:04:00.0: I iwl4965_irq_tasklet inta 0x80000000, enabled 0x00000000, fh 0x40010000
Apr  2 16:13:33 osve-sr kernel: iwlagn 0000:04:00.0: I iwl_rx_handle r = 28, i = 27, REPLY_RX, 0xc3
Apr  2 16:13:33 osve-sr kernel: iwlagn 0000:04:00.0: I iwl_rx_reply_rx Bad CRC or FIFO: 0x80000002.
Apr  2 16:13:33 osve-sr kernel: iwlagn 0000:04:00.0: I iwl4965_enable_interrupts Enabling interrupts
Apr  2 16:13:33 osve-sr kernel: iwlagn 0000:04:00.0: I __iwl_write32 write32(0x0000000C, 0xAA00008B) - drivers/net/wireless/iwlwifi/iwl-agn.c 1493


Apr  2 16:15:07 osve-sr NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 4135 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) scheduled... 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) started... 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  (wlan0): device state change: 7 -> 9 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  Activation (wlan0) failed for access point (jane-asus) 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  Marking connection 'Auto jane-asus' invalid. 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  Activation (wlan0) failed. 
Apr  2 16:15:07 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) complete. 


maybe this do you some help?

Comment 10 DongpoLiu 2009-04-02 09:11:15 UTC
Created attachment 337753 [details]
iwlwifi log to kernel-2.6.18-137.el5.jwltest.80.src.rpm

Comment 11 John W. Linville 2009-04-03 01:02:41 UTC
Alright, let's try the other patch between 2.6.29.9 and 2.6.29.10... :-)

Please give the jwltest.81 kernels a try (same location as comment 8) and post the results here...thanks!

Comment 12 DongpoLiu 2009-04-03 02:10:16 UTC
It can get associated with WPA-keyed AP readily, while fails again with WEP-Keyed AP.

attached is wpa_supplicant.log and messages.

Comment 13 DongpoLiu 2009-04-03 02:13:05 UTC
Created attachment 337964 [details]
messages to  .jwltest.81.x86_64 kernel

Comment 14 DongpoLiu 2009-04-03 02:13:57 UTC
Created attachment 337965 [details]
wpa_supplicant.log to  .jwltest.81.x86_64 kernel

Comment 15 John W. Linville 2009-04-03 18:11:22 UTC
Alright, wierd...I'm recreating this now.  My guess is that some key is not getting cleared...

Do you see this issue with iwl4965 too?

Comment 16 John W. Linville 2009-04-03 18:30:43 UTC
Reinette, does this bug sound familiar to you?  Do you recall what upstream patch might have fixed it?

Comment 17 reinette chatre 2009-04-03 20:37:46 UTC
Patch "iwlwifi: clean key table in iwl_clear_stations_table function" does seem relevant here ... but it sounds like you tested it and it does not work?

Please note that there were some issues with merging of the patch and part of it got lost in some releases. At some point we submitted a new patch ("iwlwifi: clean key table in iwl_clear_stations_table" ... 5e46882e2ecacd2ebd1bfba3caaa4a25ffbcb94d in wireless-testing) to correct the merging problem.

Comment 18 John W. Linville 2009-04-06 18:27:57 UTC
Unforutnately (for this situation), the -stable patch that I backported already includes the hunk from the patch you mentioned in comment 17.

Any other ideas? :-)

Comment 19 DongpoLiu 2009-04-07 02:06:02 UTC
the attached 2 log files are from iwl4965.

Comment 20 John W. Linville 2009-04-08 15:03:36 UTC
With jwltest.83 (basically the same as jwltest.81) I can get a WEP connection with NetworkManager's second try.  Dongpo, do you see this behavior?

Comment 21 John W. Linville 2009-04-08 19:35:39 UTC
I'm leaning towards a patch like the one below...

--- linux-2.6.18.noarch/drivers/net/wireless/iwlwifi/iwl-4965.c.orig	2009-04-08 15:34:51.000000000 -0400
+++ linux-2.6.18.noarch/drivers/net/wireless/iwlwifi/iwl-4965.c	2009-04-08 15:34:57.000000000 -0400
@@ -63,6 +63,7 @@ static struct iwl_mod_params iwl4965_mod
 	.enable_qos = 1,
 	.amsdu_size_8K = 1,
 	.restart_fw = 1,
+	.sw_crypto = 1,
 	/* the rest are 0 by default */
 };
 
@@ -2395,7 +2396,7 @@ MODULE_PARM_DESC(antenna, "select antenn
 module_param_named(disable, iwl4965_mod_params.disable, int, 0444);
 MODULE_PARM_DESC(disable, "manually disable the radio (default 0 [radio on])");
 module_param_named(swcrypto, iwl4965_mod_params.sw_crypto, int, 0444);
-MODULE_PARM_DESC(swcrypto, "using crypto in software (default 0 [hardware])");
+MODULE_PARM_DESC(swcrypto, "using crypto in software (default 1 [software])");
 module_param_named(debug, iwl4965_mod_params.debug, int, 0444);
 MODULE_PARM_DESC(debug, "debug output mask");
 module_param_named(
--- linux-2.6.18.noarch/drivers/net/wireless/iwlwifi/iwl-5000.c.orig	2009-04-08 15:31:28.000000000 -0400
+++ linux-2.6.18.noarch/drivers/net/wireless/iwlwifi/iwl-5000.c	2009-04-08 15:31:22.000000000 -0400
@@ -1520,6 +1520,7 @@ static struct iwl_mod_params iwl50_mod_p
 	.enable_qos = 1,
 	.amsdu_size_8K = 1,
 	.restart_fw = 1,
+	.sw_crypto = 1,
 	/* the rest are 0 by default */
 };
 
@@ -1574,7 +1575,7 @@ MODULE_PARM_DESC(disable50,
 		  "manually disable the 50XX radio (default 0 [radio on])");
 module_param_named(swcrypto50, iwl50_mod_params.sw_crypto, bool, 0444);
 MODULE_PARM_DESC(swcrypto50,
-		  "using software crypto engine (default 0 [hardware])\n");
+		  "using software crypto engine (default 1 [software])\n");
 module_param_named(debug50, iwl50_mod_params.debug, int, 0444);
 MODULE_PARM_DESC(debug50, "50XX debug output mask");
 module_param_named(queues_num50, iwl50_mod_params.num_of_queues, int, 0444);

Comment 22 DongpoLiu 2009-04-09 05:58:06 UTC
I did following sceneriaos on jwltest.83:

1) on os boot-up, sometimes I can get it associated with WEP-keyed AP successfully(this doesnot happen each time) ----> WPA-keyed AP successfully--->WEP-Keyed AP failed.

2) on os boot-up, I can get it associated with WPA-keyed AP successfully ----> WEP-keyed AP failed. this sceneriao happens almost each time.

3) on os boot-up, sometimes I can get it associated with open key AP successfully ----> WEP-keyed AP successfully--->open key AP successfully.

4)this version seems unstable, sometimes I find it can not get associated with open AP or WPA AP on OS boot-up.

may you find some useful at above result?

thx again.

Comment 23 John W. Linville 2009-04-09 18:25:57 UTC
Created attachment 338970 [details]
bz474699.patch

Comment 25 reinette chatre 2009-04-10 21:11:51 UTC
This patch seems relevant:

commit fc1f4c3d928eb0d21815d273d9d552a2414b52d2
Author: Mohamed Abbas <mohamed.abbas>
Date:   Wed Mar 11 11:17:59 2009 -0700

    iwlagn: fix warning when set WEP key

    iwl_clear_station_table will be called every time rxon called.
    In this function ucode_key_table is set to 0 even though a static
    WEP security is set. This will cause in many warning and might be
    an issue if dynamic WEP is set. This patch make sure we keep track
    of all existing static WEP when this function is called.

    Signed-off-by: Mohamed Abbas <mohamed.abbas>
    Signed-off-by: Reinette Chatre <reinette.chatre>
    Signed-off-by: John W. Linville <linville>

Comment 27 John W. Linville 2009-04-14 02:10:17 UTC
Re: comment 25 -- I think you are right.

New test kernels (jwltest.84) are available.  Please give those a try -- thanks!

Comment 28 DongpoLiu 2009-04-14 06:53:10 UTC
I go following sceneriaos on jwltest.84:

1) on os boot-up, I can get it associated with open key AP
successfully ----> WEP-keyed AP successfully--->open key AP successfully----> WEP-keyed AP successfully.

2) on os boot-up, I can get it associated with WEP-keyed AP successfully--->open key AP successfully ----> WEP-keyed AP successfully ---->open key AP successfully.

3) on os boot-up, I can get it associated with WEP-keyed AP
successfully ---->WPA-keyed AP successfully--->WEP-Keyed AP failed.this sceneriao happens frequeenly.

4) on os boot-up, I can get it associated with WPA-keyed AP successfully ---->
WEP-keyed AP failed. this happens frequeenly. iwl interface gets associated with WEP AP, but fails to get IP address. Log is as follows:
[root@osve-sr ~]# tail  -f  /var/log/messages                                                                                                                       
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: added 'ssid' value 'jane-asus' 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE' 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: added 'auth_alg' value 'SHARED' 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: added 'wep_key0' value '<omitted>' 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: added 'wep_tx_keyidx' value '0' 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  Config: set interface ap_scan to 1 
Apr 14 14:46:04 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 14 14:46:05 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 14 14:46:25 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected 
Apr 14 14:46:25 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 14 14:46:25 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 14 14:46:25 osve-sr kernel: iwlagn: index 0 not used in uCode key table.
Apr 14 14:46:29 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): association took too long. 
Apr 14 14:46:29 osve-sr NetworkManager: <info>  (wlan0): device state change: 5 -> 6 
Apr 14 14:46:29 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): asking for new secrets 
Apr 14 14:46:29 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected 
Apr 14 14:46:29 osve-sr kernel: iwlagn: index 0 not used in uCode key table.
Apr 14 14:46:33 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  (wlan0): device state change: 6 -> 4 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto jane-asus' has security, and secrets exist.  No new secrets needed. 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: added 'ssid' value 'jane-asus' 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE' 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: added 'auth_alg' value 'SHARED' 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: added 'wep_key0' value '<omitted>' 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: added 'wep_tx_keyidx' value '0' 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  Config: set interface ap_scan to 1 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected 
Apr 14 14:46:34 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'jane-asus'. 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  (wlan0): device state change: 5 -> 7 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction. 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  dhclient started with pid 4004 
Apr 14 14:46:35 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. 
Apr 14 14:46:35 osve-sr dhclient: Internet Systems Consortium DHCP Client V3.0.5-RedHat
Apr 14 14:46:35 osve-sr dhclient: Copyright 2004-2006 Internet Systems Consortium.
Apr 14 14:46:35 osve-sr dhclient: All rights reserved.
Apr 14 14:46:35 osve-sr dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Apr 14 14:46:35 osve-sr dhclient: 
Apr 14 14:46:35 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 14 14:46:35 osve-sr NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit 
Apr 14 14:46:35 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 14 14:46:35 osve-sr dhclient: Listening on LPF/wlan0/00:13:e8:05:4c:b9
Apr 14 14:46:35 osve-sr dhclient: Sending on   LPF/wlan0/00:13:e8:05:4c:b9
Apr 14 14:46:35 osve-sr dhclient: Sending on   Socket/fallback
Apr 14 14:46:35 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 7
Apr 14 14:46:42 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 17
Apr 14 14:46:59 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 9
Apr 14 14:47:08 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 18
Apr 14 14:47:20 osve-sr NetworkManager: <info>  Device 'wlan0' DHCP transaction took too long (>45s), stopping it. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 4004 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) scheduled... 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) started... 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): device state change: 7 -> 9 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) failed for access point (jane-asus) 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Marking connection 'Auto jane-asus' invalid. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) failed. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) complete. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): device state change: 9 -> 3 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): deactivating device (reason: 0). 
Apr 14 14:47:21 osve-sr kernel: iwlagn: index 0 not used in uCode key table.
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Policy set 'System eth0' (eth0) as default for routing and DNS. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) starting connection 'Auto jane-linksys' 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): device state change: 3 -> 4 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> disconnected 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto jane-linksys' has security, and secrets exist.  No new secrets needed. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Config: added 'ssid' value 'jane-linksys' 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK' 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Config: added 'psk' value '<omitted>' 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  Config: set interface ap_scan to 1 
Apr 14 14:47:21 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 14 14:47:23 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 14 14:47:43 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected 
Apr 14 14:47:43 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 14 14:47:45 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 14 14:47:46 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): association took too long. 
Apr 14 14:47:46 osve-sr NetworkManager: <info>  (wlan0): device state change: 5 -> 6 
Apr 14 14:47:46 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): asking for new secrets 
Apr 14 14:47:46 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected 
Apr 14 14:47:53 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 



Summary:
1)the version of driver gets more stable in comparsion with previous versions.
2) get associated with WPA AP OK
3) get associated with open key AP OK
4) get associated with WEP AP on OS bootup OK
5) failed to switch between WPA ----> WEP frequently, although I do see sometimes it works.

we are on the right way and get nearer and nearer to final goal: fix this issue totally.

Thx again

Dongpo

Comment 29 John W. Linville 2009-04-17 15:44:01 UTC
Now when you experience "failed to switch between WPA ----> WEP" (scenario 5 from comment 28), is the failure permanent?  Or does the connection succeed after multiple tries?

Comment 30 Don Zickus 2009-04-20 17:11:10 UTC
in kernel-2.6.18-140.el5
You can download this test kernel from http://people.redhat.com/dzickus/el5

Please do NOT transition this bugzilla state to VERIFIED until our QE team
has sent specific instructions indicating when to do so.  However feel free
to provide a comment indicating that this fix has been verified.

Comment 32 John W. Linville 2009-04-20 17:55:03 UTC
Please respond to comment 29.  Time is short before the RHEL5.4 patch
deadline, and I need to decide whether to submit the three patches ("iwlwifi:
clean key table in iwl_clear_stations_table function", "iwlagn: fix RX skb
alignment", and "iwlagn: fix warning when set WEP key") or just settle for
disabling hardware encryption by default.

Comment 34 Don Zickus 2009-04-21 19:51:23 UTC
moving back to POST to pick up the new changes

Comment 35 DongpoLiu 2009-04-22 02:15:13 UTC
(In reply to comment #29)
> Now when you experience "failed to switch between WPA ----> WEP" (scenario 5
> from comment 28), is the failure permanent? 
WPA ----> WEP fails frequently, although seldomly I can see WPA ----> WEP successfully
> Or does the connection succeed after multiple tries?  
after associated with WPA AP, I tried about 6 times to get associated with WEP AP, it still failed.

Comment 37 DongpoLiu 2009-04-23 02:39:11 UTC
(In reply to comment #30)
> in kernel-2.6.18-140.el5
> You can download this test kernel from http://people.redhat.com/dzickus/el5
> Please do NOT transition this bugzilla state to VERIFIED until our QE team
> has sent specific instructions indicating when to do so.  However feel free
> to provide a comment indicating that this fix has been verified.  

I did a full test to this version of kernel:
1) on os boot-up, I can get it associated with open key AP
successfully ----> WEP-keyed AP successfully--->open key AP successfully---->
WEP-keyed AP successfully.

2) on os boot-up, I can get it associated with WEP-keyed AP
successfully--->open key AP successfully ----> WEP-keyed AP successfully
---->open key AP successfully.

3) on os boot-up, I can get it associated with WEP-keyed AP
successfully ---->WPA-keyed AP successfully--->WEP-Keyed AP successfully.

4) on os boot-up, I can get it associated with WPA-keyed AP successfully ---->
WEP-keyed AP successfully. 

5) on os boot-up, I can get it associated with WPA-keyed AP
successfully--->open key AP successfully ----> WPA-keyed AP successfully
---->open key AP successfully.

all seems fine now, and this defect can be marked as fixed at this kernel release (2.6.18-140.el5), did you add some new patches to this issue?

BTW, at 138.el5.jwltest.84, WEP <---> WPA fails frequently.

Comment 38 John W. Linville 2009-04-23 14:13:30 UTC
*** Bug 476777 has been marked as a duplicate of this bug. ***

Comment 39 Don Zickus 2009-04-27 15:58:23 UTC
in kernel-2.6.18-141.el5
You can download this test kernel from http://people.redhat.com/dzickus/el5

Please do NOT transition this bugzilla state to VERIFIED until our QE team
has sent specific instructions indicating when to do so.  However feel free
to provide a comment indicating that this fix has been verified.

Comment 40 DongpoLiu 2009-04-29 01:20:29 UTC
we get a strange issue at kernel-2.6.18-141.el5:
when I get the 4965 interface associated with a WEP AP successfully-->then after sometime, it will try to reassociated with a WEP AP again......
the whole wireless seems unstable all the time, this can be an issue to us?

log is as follows:
Apr 29 09:14:52 osve-sr NetworkManager: <info>  Found new 802.11 WiFi device 'wlan0'. 
Apr 29 09:14:52 osve-sr NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_13_e8_05_4c_b9 
Apr 29 09:14:52 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 29 09:14:52 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 3
Apr 29 09:14:55 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): device state change: 1 -> 2 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): preparing device. 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): deactivating device (reason: 2). 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Policy set 'System eth0' (eth0) as default for routing and DNS. 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): device state change: 2 -> 3 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) starting connection 'Auto jane-asus' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): device state change: 3 -> 4 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto jane-asus' has security, and secrets exist.  No new secrets needed. 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: added 'ssid' value 'jane-asus' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: added 'auth_alg' value 'SHARED' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: added 'wep_key0' value '<omitted>' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: added 'wep_tx_keyidx' value '0' 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  Config: set interface ap_scan to 1 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected 
Apr 29 09:14:56 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 29 09:14:57 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> disconnected 
Apr 29 09:14:59 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4
Apr 29 09:15:01 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> associating 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'jane-asus'. 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  (wlan0): device state change: 5 -> 7 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction. 
Apr 29 09:15:02 osve-sr dhclient: Internet Systems Consortium DHCP Client V3.0.5-RedHat
Apr 29 09:15:02 osve-sr dhclient: Copyright 2004-2006 Internet Systems Consortium.
Apr 29 09:15:02 osve-sr dhclient: All rights reserved.
Apr 29 09:15:02 osve-sr dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Apr 29 09:15:02 osve-sr dhclient: 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  dhclient started with pid 12538 
Apr 29 09:15:02 osve-sr kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. 
Apr 29 09:15:02 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 29 09:15:02 osve-sr NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit 
Apr 29 09:15:02 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 29 09:15:02 osve-sr dhclient: Listening on LPF/wlan0/00:13:e8:05:4c:b9
Apr 29 09:15:02 osve-sr dhclient: Sending on   LPF/wlan0/00:13:e8:05:4c:b9
Apr 29 09:15:02 osve-sr dhclient: Sending on   Socket/fallback
Apr 29 09:15:02 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 7
Apr 29 09:15:02 osve-sr dhclient: DHCPOFFER from 192.168.50.20
Apr 29 09:15:02 osve-sr dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Apr 29 09:15:02 osve-sr dhclient: DHCPACK from 192.168.50.20
Apr 29 09:15:02 osve-sr NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled... 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started... 
Apr 29 09:15:02 osve-sr NetworkManager: <info>    address 192.168.50.131 
Apr 29 09:15:02 osve-sr NetworkManager: <info>    prefix 24 (255.255.255.0) 
Apr 29 09:15:02 osve-sr NetworkManager: <info>    gateway 192.168.50.20 
Apr 29 09:15:02 osve-sr NetworkManager: <info>    hostname 'osve-sr' 
Apr 29 09:15:02 osve-sr NetworkManager: <info>    nameserver '192.168.50.20' 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled... 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete. 
Apr 29 09:15:02 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started... 
Apr 29 09:15:02 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv4 for mDNS.
Apr 29 09:15:02 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:15:02 osve-sr dhclient: bound to 192.168.50.131 -- renewal in 38935 seconds.
Apr 29 09:15:02 osve-sr avahi-daemon[3349]: Registering new address record for 192.168.50.131 on wlan0.
Apr 29 09:15:03 osve-sr NetworkManager: <info>  Policy set 'System eth0' (eth0) as default for routing and DNS. 
Apr 29 09:15:03 osve-sr NetworkManager: <info>  (wlan0): device state change: 7 -> 8 
Apr 29 09:15:03 osve-sr NetworkManager: <info>  Activation (wlan0) successful, device activated. 
Apr 29 09:15:03 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete. 
Apr 29 09:15:03 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv6 for mDNS.
Apr 29 09:15:03 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:15:03 osve-sr avahi-daemon[3349]: Registering new address record for fe80::213:e8ff:fe05:4cb9 on wlan0.
Apr 29 09:15:54 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> disconnected 
Apr 29 09:15:57 osve-sr kernel: iwlagn: Can't stop Rx DMA.
Apr 29 09:15:57 osve-sr avahi-daemon[3349]: Interface wlan0.IPv6 no longer relevant for mDNS.
Apr 29 09:15:57 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:15:57 osve-sr avahi-daemon[3349]: Interface wlan0.IPv4 no longer relevant for mDNS.
Apr 29 09:15:57 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:15:57 osve-sr kernel: ACPI: PCI interrupt for device 0000:04:00.0 disabled
Apr 29 09:15:57 osve-sr dhclient: receive_packet failed on wlan0: Network is down
Apr 29 09:15:57 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 29 09:15:57 osve-sr avahi-daemon[3349]: Withdrawing address record for fe80::213:e8ff:fe05:4cb9 on wlan0.
Apr 29 09:15:57 osve-sr avahi-daemon[3349]: Withdrawing address record for 192.168.50.131 on wlan0.
Apr 29 09:16:01 osve-sr kernel: PCI: Enabling device 0000:04:00.0 (0000 -> 0002)
Apr 29 09:16:01 osve-sr kernel: ACPI: PCI Interrupt 0000:04:00.0[A] -> GSI 19 (level, low) -> IRQ 193
Apr 29 09:16:01 osve-sr kernel: Registered led device: iwl-phy0:radio
Apr 29 09:16:01 osve-sr kernel: Registered led device: iwl-phy0:assoc
Apr 29 09:16:01 osve-sr kernel: Registered led device: iwl-phy0:RX
Apr 29 09:16:01 osve-sr kernel: Registered led device: iwl-phy0:TX
Apr 29 09:16:01 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv4 for mDNS.
Apr 29 09:16:01 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:01 osve-sr avahi-daemon[3349]: Registering new address record for 192.168.50.131 on wlan0.
Apr 29 09:16:03 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv6 for mDNS.
Apr 29 09:16:03 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:16:03 osve-sr avahi-daemon[3349]: Registering new address record for fe80::213:e8ff:fe05:4cb9 on wlan0.
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Interface wlan0.IPv6 no longer relevant for mDNS.
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Interface wlan0.IPv4 no longer relevant for mDNS.
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:10 osve-sr kernel: ACPI: PCI interrupt for device 0000:04:00.0 disabled
Apr 29 09:16:10 osve-sr dhclient: receive_packet failed on wlan0: Network is down
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Withdrawing address record for fe80::213:e8ff:fe05:4cb9 on wlan0.
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Withdrawing address record for 192.168.50.131 on wlan0.
Apr 29 09:16:10 osve-sr kernel: PCI: Enabling device 0000:04:00.0 (0000 -> 0002)
Apr 29 09:16:10 osve-sr kernel: ACPI: PCI Interrupt 0000:04:00.0[A] -> GSI 19 (level, low) -> IRQ 193
Apr 29 09:16:10 osve-sr kernel: Registered led device: iwl-phy0:radio
Apr 29 09:16:10 osve-sr kernel: Registered led device: iwl-phy0:assoc
Apr 29 09:16:10 osve-sr kernel: Registered led device: iwl-phy0:RX
Apr 29 09:16:10 osve-sr kernel: Registered led device: iwl-phy0:TX
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv4 for mDNS.
Apr 29 09:16:10 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:10 osve-sr NetworkManager: <info>  (wlan0): device state change: 8 -> 3 
Apr 29 09:16:10 osve-sr NetworkManager: <info>  (wlan0): deactivating device (reason: 11). 
Apr 29 09:16:10 osve-sr kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Apr 29 09:16:12 osve-sr NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 12538 
Apr 29 09:16:12 osve-sr kernel: ACPI: PCI interrupt for device 0000:04:00.0 disabled
Apr 29 09:16:12 osve-sr avahi-daemon[3349]: Registering new address record for 192.168.50.131 on wlan0.
Apr 29 09:16:12 osve-sr avahi-daemon[3349]: Interface wlan0.IPv4 no longer relevant for mDNS.
Apr 29 09:16:12 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:12 osve-sr avahi-daemon[3349]: Withdrawing address record for 192.168.50.131 on wlan0.
Apr 29 09:16:12 osve-sr kernel: PCI: Enabling device 0000:04:00.0 (0000 -> 0002)
Apr 29 09:16:12 osve-sr kernel: ACPI: PCI Interrupt 0000:04:00.0[A] -> GSI 19 (level, low) -> IRQ 193
Apr 29 09:16:12 osve-sr NetworkManager: <info>  Policy set 'System eth0' (eth0) as default for routing and DNS. 
Apr 29 09:16:13 osve-sr kernel: Registered led device: iwl-phy0:radio
Apr 29 09:16:13 osve-sr kernel: Registered led device: iwl-phy0:assoc
Apr 29 09:16:13 osve-sr kernel: Registered led device: iwl-phy0:RX
Apr 29 09:16:13 osve-sr kernel: Registered led device: iwl-phy0:TX
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv4 for mDNS.
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: Registering new address record for 192.168.50.131 on wlan0.
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: Withdrawing address record for 192.168.50.131 on wlan0.
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: iface.c: interface_mdns_mcast_join() called but no local address available.
Apr 29 09:16:13 osve-sr NetworkManager: <WARN>  nm_device_wifi_set_mode(): error setting card wlan0 to mode 2: Device or resource busy 
Apr 29 09:16:13 osve-sr avahi-daemon[3349]: Interface wlan0.IPv4 no longer relevant for mDNS.
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) starting connection 'Auto jane-asus' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  (wlan0): device state change: 3 -> 4 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto jane-asus' has security, and secrets exist.  No new secrets needed. 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: added 'ssid' value 'jane-asus' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: added 'key_mgmt' value 'NONE' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: added 'auth_alg' value 'SHARED' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: added 'wep_key0' value '<omitted>' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: added 'wep_tx_keyidx' value '0' 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  Config: set interface ap_scan to 1 
Apr 29 09:16:13 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
Apr 29 09:16:14 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv6 for mDNS.
Apr 29 09:16:14 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:16:14 osve-sr avahi-daemon[3349]: Registering new address record for fe80::213:e8ff:fe05:4cb9 on wlan0.
Apr 29 09:16:16 osve-sr kernel: ACPI: PCI interrupt for device 0000:04:00.0 disabled
Apr 29 09:16:16 osve-sr avahi-daemon[3349]: Interface wlan0.IPv6 no longer relevant for mDNS.
Apr 29 09:16:16 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:16:16 osve-sr avahi-daemon[3349]: Withdrawing address record for fe80::213:e8ff:fe05:4cb9 on wlan0.
Apr 29 09:16:16 osve-sr kernel: PCI: Enabling device 0000:04:00.0 (0000 -> 0002)
Apr 29 09:16:16 osve-sr kernel: ACPI: PCI Interrupt 0000:04:00.0[A] -> GSI 19 (level, low) -> IRQ 193
Apr 29 09:16:17 osve-sr kernel: Registered led device: iwl-phy0:radio
Apr 29 09:16:17 osve-sr kernel: Registered led device: iwl-phy0:assoc
Apr 29 09:16:17 osve-sr kernel: Registered led device: iwl-phy0:RX
Apr 29 09:16:17 osve-sr kernel: Registered led device: iwl-phy0:TX
Apr 29 09:16:17 osve-sr kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Apr 29 09:16:17 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> associating 
Apr 29 09:16:17 osve-sr kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Apr 29 09:16:17 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'jane-asus'. 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  (wlan0): device state change: 5 -> 7 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction. 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  dhclient started with pid 12690 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. 
Apr 29 09:16:17 osve-sr dhclient: Internet Systems Consortium DHCP Client V3.0.5-RedHat
Apr 29 09:16:17 osve-sr dhclient: Copyright 2004-2006 Internet Systems Consortium.
Apr 29 09:16:17 osve-sr dhclient: All rights reserved.
Apr 29 09:16:17 osve-sr dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Apr 29 09:16:17 osve-sr dhclient: 
Apr 29 09:16:17 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 29 09:16:17 osve-sr NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit 
Apr 29 09:16:17 osve-sr dhclient: wmaster0: unknown hardware address type 801
Apr 29 09:16:17 osve-sr dhclient: Listening on LPF/wlan0/00:13:e8:05:4c:b9
Apr 29 09:16:17 osve-sr dhclient: Sending on   LPF/wlan0/00:13:e8:05:4c:b9
Apr 29 09:16:17 osve-sr dhclient: Sending on   Socket/fallback
Apr 29 09:16:17 osve-sr dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 3
Apr 29 09:16:17 osve-sr dhclient: DHCPOFFER from 192.168.50.20
Apr 29 09:16:17 osve-sr dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Apr 29 09:16:17 osve-sr dhclient: DHCPACK from 192.168.50.20
Apr 29 09:16:17 osve-sr NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled... 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started... 
Apr 29 09:16:17 osve-sr NetworkManager: <info>    address 192.168.50.131 
Apr 29 09:16:17 osve-sr NetworkManager: <info>    prefix 24 (255.255.255.0) 
Apr 29 09:16:17 osve-sr NetworkManager: <info>    gateway 192.168.50.20 
Apr 29 09:16:17 osve-sr NetworkManager: <info>    hostname 'osve-sr' 
Apr 29 09:16:17 osve-sr NetworkManager: <info>    nameserver '192.168.50.20' 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled... 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete. 
Apr 29 09:16:17 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started... 
Apr 29 09:16:17 osve-sr dhclient: bound to 192.168.50.131 -- renewal in 40003 seconds.
Apr 29 09:16:17 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv4 for mDNS.
Apr 29 09:16:17 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:17 osve-sr avahi-daemon[3349]: Registering new address record for 192.168.50.131 on wlan0.
Apr 29 09:16:18 osve-sr NetworkManager: <info>  Policy set 'System eth0' (eth0) as default for routing and DNS. 
Apr 29 09:16:18 osve-sr NetworkManager: <info>  (wlan0): device state change: 7 -> 8 
Apr 29 09:16:18 osve-sr NetworkManager: <info>  Activation (wlan0) successful, device activated. 
Apr 29 09:16:18 osve-sr NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete. 
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Withdrawing address record for 192.168.50.131 on wlan0.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.131.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: iface.c: interface_mdns_mcast_join() called but no local address available.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Interface wlan0.IPv4 no longer relevant for mDNS.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv4 for mDNS.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.174.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Registering new address record for 192.168.50.174 on wlan0.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: New relevant interface wlan0.IPv6 for mDNS.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::213:e8ff:fe05:4cb9.
Apr 29 09:16:19 osve-sr avahi-daemon[3349]: Registering new address record for fe80::213:e8ff:fe05:4cb9 on wlan0.

Comment 41 DongpoLiu 2009-04-29 01:25:26 UTC
In addition, NetworkManager will crash frequently at this version of Kernel, and the whole OS seems unstable.

Comment 42 John W. Linville 2009-04-29 14:31:10 UTC
Dongpo, please open a new bug for the specific new problem you are reporting.  Please include details about hardware (e.g. iwl4965), wireless environment (including wireless security in use), etc.  Also, please indicate whether or not VT-d is enabled.

FWIW, the rhel5 iwl4965 box I have is working just fine for me in my home environment.

Comment 43 Jane Lv 2009-05-06 05:21:14 UTC
(In reply to comment #42)
> Dongpo, please open a new bug for the specific new problem you are reporting. 
> Please include details about hardware (e.g. iwl4965), wireless environment
> (including wireless security in use), etc.  Also, please indicate whether or
> not VT-d is enabled.
> 
> FWIW, the rhel5 iwl4965 box I have is working just fine for me in my home
> environment.  

John,

Dongpo is taking 2 weeks vacation now.  I'm taking the wireless testing during this period.

I tried iwl4965 with kernel-2.6.18-141, everything works fine for me.  So far, I didn't see the driver unstable issue and NetworkManager crash issue mentioned by Dongpo in comment #40 and #41.  I'm keeping an eye on this and will open a new bug if it really happens to me.

Comment 47 errata-xmlrpc 2009-09-02 08:27:58 UTC
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2009-1243.html