Debugging with Network Manager

[Bill Moseley <moseley hank org>]

I'm running Ubuntu Gutsy on a T60p Thinkpad.

I'm at a location with wireless.  I can sometimes connect -- other
times it will attempt to connect for a number of minutes then finally
ask for the pass phrase as if it connected by the stored pass phrase
is no longer valid.  I enter the correct pass phrase and then it asks
for the phrase again.

And other times the AP will not show up in nm-applet but scanning with
iwlist will show the AP.

It's been a frustrating experience because I also have a iBook running
OS X and wireless is working perfectly.

What I'd like is to be more effective in debugging problems.  Are
there any docs or howtos available that explain steps in debugging
wireless issues with Network Manager?  For those of you very familiar with
Network Manager what steps would you use to debug failing wireless?

Here's some logs from earlier today:

[lots of NM debugging trimmed]

Nov 23 08:11:51 tiger NetworkManager: <info>  ath0: Device is fully-supported using driver 'ath_pci'.+
Nov 23 08:11:51 tiger NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start+
Nov 23 08:11:51 tiger NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing.+
Nov 23 08:11:51 tiger NetworkManager: <info>  Now managing wireless (802.11) device 'ath0'.+
Nov 23 08:11:51 tiger NetworkManager: <info>  Deactivating device ath0.+
Nov 23 08:11:51 tiger NetworkManager: <debug> [1195834311.189296] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/net_00_1a_6b_68_b3_ad').+
Nov 23 08:11:51 tiger NetworkManager: <info>  eth0: Device is fully-supported using driver 'e1000'.+
Nov 23 08:11:51 tiger NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start+
Nov 23 08:11:51 tiger NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing.+
Nov 23 08:11:51 tiger NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth0'.+
Nov 23 08:11:51 tiger NetworkManager: <info>  Deactivating device eth0.+
Nov 23 08:11:51 tiger kernel: [   26.652000] NET: Registered protocol family 10
Nov 23 08:11:51 tiger kernel: [   26.652000] lo: Disabled Privacy Extensions
Nov 23 08:11:51 tiger kernel: [   26.652000] ADDRCONF(NETDEV_UP): eth0: link is not ready

[more <debug>]

Nov 23 08:12:46 tiger NetworkManager: <info>  Updating allowed wireless network lists.+
Nov 23 08:12:46 tiger NetworkManager: <info>  SWITCH: no current connection, found better connection 'ath0'.+
Nov 23 08:12:46 tiger dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/ath0 for sub-path ath0.dbus.get.reason
Nov 23 08:12:46 tiger NetworkManager: <info>  Will activate connection 'ath0/whmlan'.+
Nov 23 08:12:46 tiger NetworkManager: <info>  Device ath0 activation scheduled...+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) started...+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) Stage 1 of 5 (Device Prepare) started...+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) Stage 1 of 5 (Device Prepare) complete.+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) Stage 2 of 5 (Device Configure) starting...+
Nov 23 08:12:46 tiger NetworkManager: <info>  Old device 'ath0' activating, won't change.+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0/wireless): access point 'whmlan' is encrypted, but NO valid key exists.  New key needed.+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) New wireless user key requested for network 'whmlan'.+
Nov 23 08:12:46 tiger NetworkManager: <info>  Activation (ath0) Stage 2 of 5 (Device Configure) complete.+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0) New wireless user key for network 'whmlan' received.+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0) Stage 1 of 5 (Device Prepare) started...+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0) Stage 1 of 5 (Device Prepare) complete.+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0) Stage 2 of 5 (Device Configure) starting...+
Nov 23 08:12:50 tiger NetworkManager: <info>  Activation (ath0/wireless): access point 'whmlan' is encrypted, and a key exists.  No new key needed.+
Nov 23 08:12:51 tiger NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (0/10).+
Nov 23 08:12:52 tiger NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (1/10).+
Nov 23 08:12:52 tiger NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (2/10).+
Nov 23 08:12:52 tiger NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (3/10).+
Nov 23 08:12:52 tiger NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (4/10).+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'INTERFACE_ADD ath0^I^Imadwifi^I/var/run/wpa_supplicant3^I'+
Nov 23 08:12:52 tiger kernel: [   87.944000] NET: Registered protocol family 17
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  supplicant_init() - connect to device ctrl socket (1/10).+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'AP_SCAN 1'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'ADD_NETWORK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was '0'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 ssid 77686d6c616e'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 proto WPA'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 key_mgmt WPA-PSK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 psk <key>'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: sending command 'ENABLE_NETWORK 0'+
Nov 23 08:12:52 tiger NetworkManager: <info>  SUP: response was 'OK'+
Nov 23 08:12:52 tiger NetworkManager: <info>  Activation (ath0) Stage 2 of 5 (Device Configure) complete.+
Nov 23 08:13:08 tiger NetworkManager: <info>  Old device 'ath0' activating, won't change.+
Nov 23 08:13:29 tiger NetworkManager: <info>  Old device 'ath0' activating, won't change.+
Nov 23 08:13:33 tiger NetworkManager: <info>  Activation (ath0/wireless): disconnected during association, asking for new key.+
Nov 23 08:13:33 tiger NetworkManager: <info>  Activation (ath0) New wireless user key requested for network 'whmlan'.+
Nov 23 08:13:54 tiger NetworkManager: <info>  ath0: link timed out.+
Nov 23 08:14:37 tiger last message repeated 2 times





-- 
Bill Moseley
moseley hank org