Re: Debugging with Network Manager

[Dan Williams <dcbw redhat com>]

On Fri, 2007-11-23 at 09:07 -0800, Bill Moseley wrote:
> 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.

Nov 23 08:13:33 tiger NetworkManager: <info>  Activation (ath0/wireless): disconnected during association, asking for new key.+

It looks like the driver is telling wpa_supplicant that it's
disconnected from the AP during the association.  That is usually
because the AP disassociated you because your authentication credentials
are wrong, hence why NM asks for a new key.  How far away are you from
the AP?  Can you run 'iwevent ath0' during the association and reply
with what you get?

Dan

> 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
> 
> 
> 
> 
>