Re: 2.6.24.3-12.fc8 kernel causes NM to fail to connect, 2.6.23.15-137.fc8 works perfectly

[Dan Williams <dcbw redhat com>]

On Sun, 2008-03-16 at 00:09 +0000, Brian Morrison wrote:
> On Sat, 8 Mar 2008 17:50:59 +0000
> Brian Morrison <bdm fenrir org uk> wrote:
> 
> > On Sat, 8 Mar 2008 17:44:42 +0000
> > Brian Morrison <bdm fenrir org uk> wrote:
> > 
> > > If someone would like to tell me what sort of debugging I can do, I'll
> > > happily do so and post the results here.
> > 
> > Should have added, it's an Intel 3945ABG card using the iwl3945
> > drivers. I don't think they or NM were updated in this batch of
> > updates....<checks>...no, only NM-openvpn which I'm not using just now.
> > 
> > So, looks like the kernel is the culprit although it might be that the
> > new kernel wireless fixes are correct and NM was working around
> > something in the previous kernel.
> > 
> 
> I've now had some time to generate some logs, basically grepping for
> NetworkManager in /var/log/messages, which I'm going to post here.
> 
> First of all a good log, using the 2.6.23.15-137 kernel:
> 
> Mar 15 23:21:09 fangio NetworkManager: <info>  starting...
> Mar 15 23:21:09 fangio NetworkManager: <info>  Found radio killswitch /org/freedesktop/Hal/devices/ipw_wlan_switch
> Mar 15 23:21:09 fangio NetworkManager: <info>  eth0: Device is fully-supported using driver 'sky2'.
> Mar 15 23:21:09 fangio NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth0'.
> Mar 15 23:21:09 fangio NetworkManager: <info>  Bringing up device eth0
> Mar 15 23:21:09 fangio NetworkManager: <info>  Deactivating device eth0.
> Mar 15 23:21:09 fangio NetworkManager: <info>  (eth0): exporting device as /org/freedesktop/Hal/devices/net_00_e0_b8_c5_e6_f4
> Mar 15 23:21:09 fangio NetworkManager: <info>  wlan0: Device is fully-supported using driver 'iwl3945'.
> Mar 15 23:21:09 fangio NetworkManager: <info>  wlan0: driver supports SSID scans (scan_capa 0x01).
> Mar 15 23:21:09 fangio NetworkManager: <info>  Now managing wireless (802.11) device 'wlan0'.
> Mar 15 23:21:09 fangio NetworkManager: <info>  Bringing up device wlan0
> Mar 15 23:21:09 fangio NetworkManager: <info>  Deactivating device wlan0.
> Mar 15 23:21:09 fangio NetworkManager: <info>  (wlan0): exporting device as /org/freedesktop/Hal/devices/net_00_19_d2_83_aa_bd
> Mar 15 23:21:15 fangio NetworkManager: <info>  Trying to start the supplicant...
> Mar 15 23:21:15 fangio NetworkManager: <info>  (eth0) supplicant interface is now in state 1 (from 0).
> Mar 15 23:21:15 fangio NetworkManager: <info>  (wlan0) supplicant manager is now in state 1 (from 0).
> Mar 15 23:21:15 fangio NetworkManager: <info>  (eth0) supplicant interface is now in state 2 (from 1).
> Mar 15 23:21:15 fangio NetworkManager: <info>  (wlan0) supplicant interface is now in state 2 (from 1).
> Mar 15 23:22:58 fangio NetworkManager: <info>  SWITCH: no current connection, found better connection 'Auto f3nr1r (wlan0)'.
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activating device wlan0
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0/wireless): access point 'Auto f3nr1r' has security, but secrets are required.
> Mar 15 23:22:58 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
> Mar 15 23:23:08 fangio NetworkManager: Missing or invalid key management
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto f3nr1r' has security, and secrets exist.  No new secrets needed.
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: added 'ssid' value 'f3nr1r'
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK'
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: added 'psk' value '<omitted>'
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: added 'proto' value 'WPA RSN'
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: added 'pairwise' value 'TKIP CCMP'
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
> Mar 15 23:23:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
> Mar 15 23:23:08 fangio NetworkManager: <info>  Config: set interface ap_scan to 1
> Mar 15 23:23:08 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 1 -> 2
> Mar 15 23:23:11 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 2 -> 3
> Mar 15 23:23:11 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 3 -> 4
> Mar 15 23:23:13 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 4 -> 0
> Mar 15 23:23:13 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 0 -> 2
> Mar 15 23:23:16 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 2 -> 3
> Mar 15 23:23:16 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 3 -> 4
> Mar 15 23:23:16 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 4 -> 5
> Mar 15 23:23:16 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 5 -> 6
> Mar 15 23:23:17 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 6 -> 7
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'f3nr1r'.
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
> Mar 15 23:23:17 fangio NetworkManager: <info>  dhclient started with pid 3437
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
> Mar 15 23:23:17 fangio NetworkManager: <info>  DHCP: device wlan0 state changed (null) -> preinit
> Mar 15 23:23:17 fangio NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
> Mar 15 23:23:17 fangio NetworkManager: <info>    address 10.0.0.4
> Mar 15 23:23:17 fangio NetworkManager: <info>    netmask 255.0.0.0
> Mar 15 23:23:17 fangio NetworkManager: <info>    broadcast 10.255.255.255
> Mar 15 23:23:17 fangio NetworkManager: <info>    gateway 10.0.0.64
> Mar 15 23:23:17 fangio NetworkManager: <info>    nameserver '10.0.0.1'
> Mar 15 23:23:17 fangio NetworkManager: <info>    nameserver '10.0.0.2'
> Mar 15 23:23:17 fangio NetworkManager: <info>    domain name 'fenrir.org.uk'
> Mar 15 23:23:17 fangio NetworkManager: <info>    nis domain 'fenrir.org.uk'
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
> Mar 15 23:23:17 fangio NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
> Mar 15 23:23:19 fangio NetworkManager: <info>  Activation (wlan0) successful, device activated.
> Mar 15 23:23:19 fangio NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
> Mar 15 23:24:57 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 7 -> 6
> Mar 15 23:24:57 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 6 -> 7
> Mar 15 23:29:54 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 7 -> 6
> Mar 15 23:29:54 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 6 -> 7
> Mar 15 23:34:43 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 7 -> 6
> Mar 15 23:34:43 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 6 -> 7
> Mar 15 23:39:42 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 7 -> 6
> Mar 15 23:39:42 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 6 -> 7
> Mar 15 23:42:06 fangio NetworkManager: <info>  Deactivating device wlan0.
> Mar 15 23:42:06 fangio NetworkManager: <info>  wlan0: canceled DHCP transaction, dhclient pid 3437
> Mar 15 23:42:08 fangio NetworkManager: <WARN>  nm_signal_handler(): Caught signal 15, shutting down normally.
> Mar 15 23:42:08 fangio NetworkManager: <info>  Bringing down device eth0
> Mar 15 23:42:08 fangio NetworkManager: <info>  Deactivating device eth0.
> Mar 15 23:42:08 fangio NetworkManager: <info>  Bringing down device wlan0
> Mar 15 23:42:08 fangio NetworkManager: <info>  Deactivating device wlan0.
> 
> and then the 2.6.24.3-12 kernel:
> 
> Mar 15 23:43:31 fangio NetworkManager: <info>  starting...
> Mar 15 23:43:31 fangio NetworkManager: <info>  Found radio killswitch /org/freedesktop/Hal/devices/ipw_wlan_switch
> Mar 15 23:43:31 fangio NetworkManager: <info>  eth0: Device is fully-supported using driver 'sky2'.
> Mar 15 23:43:31 fangio NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth0'.
> Mar 15 23:43:31 fangio NetworkManager: <info>  Bringing up device eth0
> Mar 15 23:43:31 fangio NetworkManager: <info>  Deactivating device eth0.
> Mar 15 23:43:31 fangio NetworkManager: <info>  (eth0): exporting device as /org/freedesktop/Hal/devices/net_00_e0_b8_c5_e6_f4
> Mar 15 23:43:31 fangio NetworkManager: <info>  wlan0: Device is fully-supported using driver 'iwl3945'.
> Mar 15 23:43:31 fangio NetworkManager: <info>  wlan0: driver supports SSID scans (scan_capa 0x01).
> Mar 15 23:43:31 fangio NetworkManager: <info>  Now managing wireless (802.11) device 'wlan0'.
> Mar 15 23:43:31 fangio NetworkManager: <info>  Bringing up device wlan0
> Mar 15 23:43:32 fangio NetworkManager: <info>  Deactivating device wlan0.
> Mar 15 23:43:32 fangio NetworkManager: <info>  (wlan0): exporting device as /org/freedesktop/Hal/devices/net_00_19_d2_83_aa_bd
> Mar 15 23:43:37 fangio NetworkManager: <info>  Trying to start the supplicant...
> Mar 15 23:43:38 fangio NetworkManager: <info>  (eth0) supplicant interface is now in state 1 (from 0).
> Mar 15 23:43:38 fangio NetworkManager: <info>  (wlan0) supplicant manager is now in state 1 (from 0).
> Mar 15 23:43:38 fangio NetworkManager: <info>  (eth0) supplicant interface is now in state 2 (from 1).
> Mar 15 23:43:38 fangio NetworkManager: <info>  (wlan0) supplicant interface is now in state 2 (from 1).
> Mar 15 23:44:01 fangio NetworkManager: <info>  SWITCH: no current connection, found better connection 'Auto f3nr1r (wlan0)'.
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activating device wlan0
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0/wireless): access point 'Auto f3nr1r' has security, but secrets are required.
> Mar 15 23:44:01 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
> Mar 15 23:44:06 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 2 -> 1
> Mar 15 23:44:08 fangio NetworkManager: Missing or invalid key management
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto f3nr1r' has security, and secrets exist.  No new secrets needed.
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: added 'ssid' value 'f3nr1r'
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK'
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: added 'psk' value '<omitted>'
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: added 'proto' value 'WPA RSN'
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: added 'pairwise' value 'TKIP CCMP'
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
> Mar 15 23:44:08 fangio NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
> Mar 15 23:44:08 fangio NetworkManager: <info>  Config: set interface ap_scan to 1
> Mar 15 23:44:08 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 1 -> 2
> Mar 15 23:44:10 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 2 -> 3
> Mar 15 23:44:25 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 3 -> 0
> Mar 15 23:44:25 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 0 -> 2
> Mar 15 23:44:28 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 2 -> 3
> Mar 15 23:44:33 fangio NetworkManager: <info>  Activation (wlan0/wireless): association took too long, asking for new key.
> Mar 15 23:44:33 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 3 -> 0
> Mar 15 23:44:45 fangio NetworkManager: <info>  wlan0: link timed out.
> Mar 15 23:44:58 fangio NetworkManager: <info>  (wlan0) Supplicant interface state change: 0 -> 2
> 
> If anyone can suggest some further diagnostics, I'll be happy to
> perform them, but other than the kernel version all the other settings
> and NM packages are unchanged.
> 
> Naturally I'd like to get to the bottom of this, it seems to be a
> timeout after 25 seconds where the working kernel version takes 11
> seconds to associate with my AP, but I can't see why it should be any
> different for the new kernel. 

I think this kernel is just borked; you'll want to try a newer one
(there are a few in updates-testing already).  This particular kernel
update was bad and should never have been pushed.

Dan