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

[Brian Morrison <bdm fenrir org uk>]

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. 

-- 

Brian Morrison

bdm at fenrir dot org dot uk

   "Arguing with an engineer is like wrestling with a pig in the mud;
    after a while you realize you are muddy and the pig is enjoying it."
    
GnuPG key ID DE32E5C5 - http://wwwkeys.uk.pgp.net/pgpnet/wwwkeys.html