Helmut Schaa wrote:
Am Mittwoch, 7. November 2007 08:16:03 schrieb Joe Emenaker:- Then, when I manually select my home network, NM configures and gets and IP and everything is great.... for about 15 seconds... and then the connection vanishes. (At this point, the tray icon indicates that I'm NOT connected). At this point, if I manually connect to my home net again, *this* time, it sticks.The NetworkManager-logfile would be great for tracking this issue down :)
Okay... you asked for it. :)Following is a "grep NetworkManager daemon.log" starting from a resume-from-disk. At 00:55:47, I manually tried to connect to "JoeHome", which succeeded. At 00:55:53 (6 seconds later), it finishes. Then, at 00:56:20 (27 seconds after that), there's the message "SWITCH: terminating current connection 'eth1' because it's no longer valid." and eth1 is deactivated. Now, I'd suspect that there's some weirdness with the resume-from-disk resetting the network interfaces, but this happens even if I resume the laptop and let it sit for a few minutes to let the resume process finish reloading any blacklisted modules that it had unloaded prior to hibernating.
So... I'm hoping that these logs make sense to someone.... ---------- Begin included text -----------Nov 11 00:50:46 localhost NetworkManager: <debug> [1194771046.250060] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_2_if0_bluetooth_hci_0'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.178553] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_2_if1'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.180065] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_2_if2'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.181347] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_2_usbraw'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.183713] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_2_if0'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.198402] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_3'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.263957] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_3_if0'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.276763] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_3_if1'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.296716] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_3_if0_bluetooth_hci_0'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.356726] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_3_if2'). Nov 11 00:50:49 localhost NetworkManager: <debug> [1194771049.375645] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/usb_device_413c_8000_noserial_3_usbraw'). Nov 11 00:50:51 localhost NetworkManager: <debug> [1194771051.033209] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/computer_logicaldev_input_0'). Nov 11 00:50:51 localhost NetworkManager: <debug> [1194771051.070755] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/computer_logicaldev_input_1'). Nov 11 00:50:51 localhost NetworkManager: <debug> [1194771051.086200] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/computer_logicaldev_input_2'). Nov 11 00:52:42 localhost NetworkManager: <info> DHCP daemon state is now 10 (unknown) for interface eth1 Nov 11 00:52:43 localhost NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface eth1 Nov 11 00:53:44 localhost NetworkManager: <info> DHCP daemon state is now 14 (normal exit) for interface eth1 Nov 11 00:55:29 localhost NetworkManager: <debug> [1194771329.917683] nm_device_802_11_wireless_get_activation_ap(): Forcing AP 'JoeHome' Nov 11 00:55:29 localhost NetworkManager: <info> User Switch: /org/freedesktop/NetworkManager/Devices/eth1 / JoeHome
Nov 11 00:55:29 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:55:29 localhost NetworkManager: <info> Device eth1 activation scheduled... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) started... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete. Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1/wireless): access point 'JoeHome' is encrypted, but NO valid key exists. New key needed. Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) New wireless user key requested for network 'JoeHome'. Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete. Nov 11 00:55:29 localhost NetworkManager: <WARN> nm_dbus_get_user_key_for_network_cb(): nm_dbus_get_user_key_for_network_cb(): dbus returned an error. (org.freedesktop.NetworkManagerInfo.GetKeyError) org.freedesktop.NetworkManagerInfo.GetKeyError Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) failure scheduled... Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) failed for access point (JoeHome)
Nov 11 00:55:29 localhost NetworkManager: <info> Activation (eth1) failed. Nov 11 00:55:29 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:55:39 localhost NetworkManager: <debug> [1194771339.991731] nm_device_802_11_wireless_get_activation_ap(): Forcing AP 'Target2' Nov 11 00:55:39 localhost NetworkManager: <info> User Switch: /org/freedesktop/NetworkManager/Devices/eth1 / Target2
Nov 11 00:55:39 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:55:39 localhost NetworkManager: <info> Device eth1 activation scheduled... Nov 11 00:55:39 localhost NetworkManager: <info> Activation (eth1) started... Nov 11 00:55:39 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled... Nov 11 00:55:39 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started... Nov 11 00:55:39 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled... Nov 11 00:55:39 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete. Nov 11 00:55:39 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting... Nov 11 00:55:40 localhost NetworkManager: <info> Activation (eth1/wireless): access point 'Target2' is encrypted, but NO valid key exists. New key needed. Nov 11 00:55:40 localhost NetworkManager: <info> Activation (eth1) New wireless user key requested for network 'Target2'. Nov 11 00:55:40 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete. Nov 11 00:55:41 localhost NetworkManager: <WARN> nm_dbus_get_user_key_for_network_cb(): nm_dbus_get_user_key_for_network_cb(): dbus returned an error. (org.freedesktop.NetworkManagerInfo.GetKeyError) org.freedesktop.NetworkManagerInfo.GetKeyError Nov 11 00:55:41 localhost NetworkManager: <info> Activation (eth1) failure scheduled... Nov 11 00:55:41 localhost NetworkManager: <info> Activation (eth1) failed for access point (Target2)
Nov 11 00:55:41 localhost NetworkManager: <info> Activation (eth1) failed. Nov 11 00:55:41 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:55:47 localhost NetworkManager: <debug> [1194771347.423836] nm_device_802_11_wireless_get_activation_ap(): Forcing AP 'JoeHome' Nov 11 00:55:47 localhost NetworkManager: <info> User Switch: /org/freedesktop/NetworkManager/Devices/eth1 / JoeHome
Nov 11 00:55:47 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:55:47 localhost NetworkManager: <info> Device eth1 activation scheduled... Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1) started... Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled... Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started... Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled... Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete. Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting... Nov 11 00:55:47 localhost NetworkManager: <info> Activation (eth1/wireless): access point 'JoeHome' is encrypted, and a key exists. No new key needed. Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'INTERFACE_ADD eth1 wext /var/run/wpa_supplicant '
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'AP_SCAN 1'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'ADD_NETWORK'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was '0'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 ssid 4a6f65486f6d65'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 proto WPA'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 key_mgmt WPA-PSK'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 psk <key>'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> SUP: sending command 'ENABLE_NETWORK 0'
Nov 11 00:55:48 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:55:48 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete. Nov 11 00:55:48 localhost NetworkManager: <info> Activation (eth1/wireless) Stage 2 of 5 (Device Configure) successful. Connected to access point 'JoeHome'. Nov 11 00:55:48 localhost NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) scheduled. Nov 11 00:55:48 localhost NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) started... Nov 11 00:55:50 localhost NetworkManager: <info> Activation (eth1) Beginning DHCP transaction. Nov 11 00:55:50 localhost NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) complete. Nov 11 00:55:50 localhost NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface eth1 Nov 11 00:55:50 localhost NetworkManager: <info> Old device 'eth1' activating, won't change. Nov 11 00:55:51 localhost NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface eth1 Nov 11 00:55:52 localhost NetworkManager: <info> DHCP daemon state is now 2 (bound) for interface eth1 Nov 11 00:55:52 localhost NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Get) scheduled... Nov 11 00:55:52 localhost NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Get) started... Nov 11 00:55:52 localhost NetworkManager: <info> Retrieved the following IP4 configuration from the DHCP daemon:
Nov 11 00:55:52 localhost NetworkManager: <info> address 192.168.1.101 Nov 11 00:55:52 localhost NetworkManager: <info> netmask 255.255.255.0 Nov 11 00:55:52 localhost NetworkManager: <info> broadcast 192.168.1.255 Nov 11 00:55:52 localhost NetworkManager: <info> gateway 192.168.1.1 Nov 11 00:55:52 localhost NetworkManager: <info> nameserver 129.65.16.254 Nov 11 00:55:52 localhost NetworkManager: <info> nameserver 129.65.21.254 Nov 11 00:55:52 localhost NetworkManager: <info> nameserver 66.215.64.14Nov 11 00:55:52 localhost NetworkManager: <info> Activation (eth1) Stage 5 of 5 (IP Configure Commit) scheduled... Nov 11 00:55:52 localhost NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Get) complete. Nov 11 00:55:52 localhost NetworkManager: <info> Activation (eth1) Stage 5 of 5 (IP Configure Commit) started... Nov 11 00:55:53 localhost NetworkManager: <info> DHCP returned name servers but system has disabled dynamic modification! Nov 11 00:55:53 localhost NetworkManager: <info> Activation (eth1) successful, device activated. Nov 11 00:55:53 localhost NetworkManager: <info> Activation (eth1) Finish handler scheduled. Nov 11 00:55:53 localhost NetworkManager: <info> Activation (eth1) Stage 5 of 5 (IP Configure Commit) complete. Nov 11 00:56:20 localhost NetworkManager: <info> SWITCH: terminating current connection 'eth1' because it's no longer valid.
Nov 11 00:56:20 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:56:22 localhost NetworkManager: nm_device_is_802_3_ethernet: assertion `dev != NULL' failed Nov 11 00:56:22 localhost NetworkManager: nm_device_is_802_11_wireless: assertion `dev != NULL' failed Nov 11 00:56:29 localhost NetworkManager: <debug> [1194771389.886017] nm_device_802_11_wireless_get_activation_ap(): Forcing AP 'JoeHome' Nov 11 00:56:29 localhost NetworkManager: <info> User Switch: /org/freedesktop/NetworkManager/Devices/eth1 / JoeHome
Nov 11 00:56:29 localhost NetworkManager: <info> Deactivating device eth1.Nov 11 00:56:29 localhost NetworkManager: <info> Device eth1 activation scheduled... Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1) started... Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled... Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started... Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled... Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete. Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting... Nov 11 00:56:29 localhost NetworkManager: <info> Activation (eth1/wireless): access point 'JoeHome' is encrypted, and a key exists. No new key needed. Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'INTERFACE_ADD eth1 wext /var/run/wpa_supplicant '
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'AP_SCAN 1'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'ADD_NETWORK'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was '0'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 ssid 4a6f65486f6d65'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 proto WPA'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 key_mgmt WPA-PSK'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 psk <key>'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> SUP: sending command 'ENABLE_NETWORK 0'
Nov 11 00:56:31 localhost NetworkManager: <info> SUP: response was 'OK'Nov 11 00:56:31 localhost NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete. Nov 11 00:56:31 localhost NetworkManager: <info> Activation (eth1/wireless) Stage 2 of 5 (Device Configure) successful. Connected to access point 'JoeHome'. Nov 11 00:56:31 localhost NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) scheduled. Nov 11 00:56:31 localhost NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) started... Nov 11 00:56:32 localhost NetworkManager: <info> Activation (eth1) Beginning DHCP transaction. Nov 11 00:56:32 localhost NetworkManager: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) complete. Nov 11 00:56:32 localhost NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface eth1 Nov 11 00:56:32 localhost NetworkManager: <info> Old device 'eth1' activating, won't change. Nov 11 00:56:33 localhost NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface eth1 Nov 11 00:56:37 localhost NetworkManager: <info> DHCP daemon state is now 2 (bound) for interface eth1 Nov 11 00:56:37 localhost NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Get) scheduled... Nov 11 00:56:37 localhost NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Get) started... Nov 11 00:56:37 localhost NetworkManager: <info> Retrieved the following IP4 configuration from the DHCP daemon:
Nov 11 00:56:37 localhost NetworkManager: <info> address 192.168.1.101 Nov 11 00:56:37 localhost NetworkManager: <info> netmask 255.255.255.0 Nov 11 00:56:37 localhost NetworkManager: <info> broadcast 192.168.1.255 Nov 11 00:56:37 localhost NetworkManager: <info> gateway 192.168.1.1 Nov 11 00:56:37 localhost NetworkManager: <info> nameserver 129.65.16.254 Nov 11 00:56:37 localhost NetworkManager: <info> nameserver 129.65.21.254 Nov 11 00:56:37 localhost NetworkManager: <info> nameserver 66.215.64.14Nov 11 00:56:37 localhost NetworkManager: <info> Activation (eth1) Stage 5 of 5 (IP Configure Commit) scheduled... Nov 11 00:56:37 localhost NetworkManager: <info> Activation (eth1) Stage 4 of 5 (IP Configure Get) complete. Nov 11 00:56:37 localhost NetworkManager: <info> Activation (eth1) Stage 5 of 5 (IP Configure Commit) started... Nov 11 00:56:38 localhost NetworkManager: <info> DHCP returned name servers but system has disabled dynamic modification! Nov 11 00:56:38 localhost NetworkManager: <info> Activation (eth1) Finish handler scheduled. Nov 11 00:56:38 localhost NetworkManager: <info> Activation (eth1) Stage 5 of 5 (IP Configure Commit) complete. Nov 11 00:56:38 localhost NetworkManager: <info> Activation (eth1) successful, device activated. ---------- End included text -----------
Attachment:
smime.p7s
Description: S/MIME Cryptographic Signature