Re: NM vs. suspend/resume

[Neal Becker <ndbecker2 gmail com>]

Jirka Klimes wrote:

> On Friday 24 of September 2010 13:00:58 Neal Becker wrote:
>> NetworkManager-0.8.1-6.git20100831.fc13.x86_64
>> knetworkmanager-0.9-0.20.20100603.fc13.x86_64
>> 
>> When resumed, NM does not notice wired eth0 if when suspended it was
>> running on wifi.  Restarting NM fixes it.
>> 
>> Or perhaps the problem is knetworkmanager not noticing the change?
>> 
> 
> Could you grab NetworkManager logs (var/log/messages)?
> Do you see the device in nm-tool output?
> 
> Jirka

See attached.  nm says nothing about eth0 when resumed.  Then nm is 
restarted and everything works.

Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) starting connection 'nbecker'
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 3 -> 4 (reason 0)
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> (wlan0): supplicant connection state:  scanning -> disconnected
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 4 -> 5 (reason 0)
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0/wireless): access point 'nbecker' has security, but secrets are required.
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 5 -> 6 (reason 0)
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <warn> Failed to update connection secrets: 1 802-1x
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 6 -> 4 (reason 0)
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 4 -> 5 (reason 0)
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0/wireless): connection 'nbecker' has security, and secrets exist.  No new secrets needed.
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Config: added 'ssid' value 'nbecker'
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Config: added 'scan_ssid' value '1'
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Config: added 'psk' value '<omitted>'
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Sep 24 06:47:56 nbecker1 NetworkManager[1351]: <info> Config: set interface ap_scan to 1
Sep 24 06:47:56 nbecker1 openvpn[18484]: RESOLVE: Cannot resolve host address: nbecker.dyndns.org: [TRY_AGAIN] A temporary error occurred on an authoritative name server.
Sep 24 06:47:56 nbecker1 openvpn[18484]: RESOLVE: Cannot resolve host address: nbecker.dyndns.org: [TRY_AGAIN] A temporary error occurred on an authoritative name server.
Sep 24 06:47:57 nbecker1 dhclient[23755]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
Sep 24 06:47:58 nbecker1 ntpd[1446]: Deleting interface #6 wlan0, 192.168.1.113#123, interface stats: received=142, sent=142, dropped=0, active_time=47659 secs
Sep 24 06:47:58 nbecker1 ntpd[1446]: 192.43.244.18 interface 192.168.1.113 -> (null)
Sep 24 06:47:58 nbecker1 ntpd[1446]: 216.45.57.38 interface 192.168.1.113 -> (null)
Sep 24 06:47:58 nbecker1 ntpd[1446]: 63.240.161.99 interface 192.168.1.113 -> (null)
Sep 24 06:47:58 nbecker1 NetworkManager[1351]: <info> (wlan0): supplicant connection state:  disconnected -> scanning
Sep 24 06:48:01 nbecker1 openvpn[18484]: RESOLVE: Cannot resolve host address: nbecker.dyndns.org: [TRY_AGAIN] A temporary error occurred on an authoritative name server.
Sep 24 06:48:04 nbecker1 dhclient[23755]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
Sep 24 06:48:04 nbecker1 dhclient[23755]: DHCPOFFER from 10.32.112.2
Sep 24 06:48:04 nbecker1 dhclient[23755]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Sep 24 06:48:04 nbecker1 dhclient[23755]: DHCPACK from 10.32.112.3
Sep 24 06:48:04 nbecker1 dhclient[23755]: bound to 10.32.112.161 -- renewal in 36902 seconds.
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info> (eth0): DHCPv4 state changed preinit -> bound
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   address 10.32.112.161
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   prefix 24 (255.255.255.0)
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   gateway 10.32.112.1
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   nameserver '139.85.52.104'
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   nameserver '139.85.52.102'
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   nameserver '139.85.87.105'
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   nameserver '139.85.176.102'
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info>   domain name 'hughes.com'
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
Sep 24 06:48:04 nbecker1 NetworkManager[1351]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Sep 24 06:48:04 nbecker1 avahi-daemon[1197]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.32.112.161.
Sep 24 06:48:04 nbecker1 avahi-daemon[1197]: New relevant interface eth0.IPv4 for mDNS.
Sep 24 06:48:04 nbecker1 avahi-daemon[1197]: Registering new address record for 10.32.112.161 on eth0.IPv4.
Sep 24 06:48:05 nbecker1 NetworkManager[1351]: <info> (eth0): device state change: 7 -> 8 (reason 0)
Sep 24 06:48:05 nbecker1 NetworkManager[1351]: <info> Policy set 'System eth0' (eth0) as default for IPv4 routing and DNS.
Sep 24 06:48:05 nbecker1 NetworkManager[1351]: <info> Updating /etc/hosts with new system hostname
Sep 24 06:48:05 nbecker1 ntpd[1446]: Listen normally on 9 eth0 10.32.112.161 UDP 123
Sep 24 06:48:05 nbecker1 NetworkManager[1351]: <info> Activation (eth0) successful, device activated.
Sep 24 06:48:05 nbecker1 NetworkManager[1351]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Sep 24 06:48:05 nbecker1 nm-dispatcher.action: nm_dispatcher_action: Invalid connection: '(null)' / 'connection setting not found' invalid: 1
Sep 24 06:48:06 nbecker1 ntpd[1446]: 0.0.0.0 0618 08 no_sys_peer
Sep 24 06:48:06 nbecker1 openvpn[18484]: UDPv4 link local: [undef]
Sep 24 06:48:06 nbecker1 openvpn[18484]: UDPv4 link remote: 71.168.61.157:5001
Sep 24 06:48:07 nbecker1 openvpn[18484]: [ibecker2] Peer Connection Initiated with 71.168.61.157:5001
Sep 24 06:48:09 nbecker1 openvpn[18484]: Preserving previous TUN/TAP instance: tun0
Sep 24 06:48:09 nbecker1 openvpn[18484]: Initialization Sequence Completed
Sep 24 06:48:11 nbecker1 pulseaudio[1948]: ratelimit.c: 305 events suppressed
Sep 24 06:48:22 nbecker1 NetworkManager[1351]: <warn> Activation (wlan0/wireless): association took too long.
Sep 24 06:48:22 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 5 -> 6 (reason 0)
Sep 24 06:48:22 nbecker1 NetworkManager[1351]: <warn> Activation (wlan0/wireless): asking for new secrets
Sep 24 06:48:22 nbecker1 NetworkManager[1351]: <info> (wlan0): supplicant connection state:  scanning -> disconnected
Sep 24 06:48:30 nbecker1 kernel: usb 4-2: new low speed USB device using uhci_hcd and address 7
Sep 24 06:48:30 nbecker1 kernel: usb 4-2: New USB device found, idVendor=046d, idProduct=c521
Sep 24 06:48:30 nbecker1 kernel: usb 4-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Sep 24 06:48:30 nbecker1 kernel: usb 4-2: Product: USB Receiver
Sep 24 06:48:30 nbecker1 kernel: usb 4-2: Manufacturer: Logitech
Sep 24 06:48:30 nbecker1 kernel: input: Logitech USB Receiver as /devices/pci0000:00/0000:00:1a.1/usb4/4-2/4-2:1.0/input/input18
Sep 24 06:48:30 nbecker1 kernel: generic-usb 0003:046D:C521.000B: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Receiver] on usb-0000:00:1a.1-2/input0
Sep 24 06:48:30 nbecker1 kernel: input: Logitech USB Receiver as /devices/pci0000:00/0000:00:1a.1/usb4/4-2/4-2:1.1/input/input19
Sep 24 06:48:30 nbecker1 kernel: generic-usb 0003:046D:C521.000C: input,hiddev96,hidraw1: USB HID v1.11 Device [Logitech USB Receiver] on usb-0000:00:1a.1-2/input1
Sep 24 06:48:31 nbecker1 kernel: r8169 0000:08:00.0: eth0: link down
Sep 24 06:48:31 nbecker1 NetworkManager[1351]: <info> (eth0): carrier now OFF (device state 8, deferring action for 4 seconds)
Sep 24 06:48:35 nbecker1 kernel: r8169 0000:08:00.0: eth0: link up
Sep 24 06:48:35 nbecker1 NetworkManager[1351]: <info> (eth0): carrier now ON (device state 8)
Sep 24 06:48:37 nbecker1 NetworkManager[1351]: <warn> (wlan0): link timed out.
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> caught signal 15, shutting down normally.
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> (wlan0): now unmanaged
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> (wlan0): device state change: 6 -> 1 (reason 36)
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> (wlan0): deactivating device (reason: 36).
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> (wlan0): cleaning up...
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> (wlan0): taking down device.
Sep 24 06:48:59 nbecker1 avahi-daemon[1197]: Withdrawing address record for fe80::213:e8ff:fed2:99e3 on wlan0.
Sep 24 06:48:59 nbecker1 NetworkManager[1351]: <info> exiting (success)
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> NetworkManager (version 0.8.1-6.git20100831.fc13) is starting...
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> VPN: loaded org.freedesktop.NetworkManager.openconnect
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> VPN: loaded org.freedesktop.NetworkManager.openvpn
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> VPN: loaded org.freedesktop.NetworkManager.pptp
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> VPN: loaded org.freedesktop.NetworkManager.vpnc
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> modem-manager is now available
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> monitoring kernel firmware directory '/lib/firmware'.
Sep 24 06:49:00 nbecker1 NetworkManager[24090]:    ifcfg-rh: Acquired D-Bus service com.redhat.ifcfgrh1
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> Loaded plugin ifcfg-rh: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Sep 24 06:49:00 nbecker1 NetworkManager[24090]:    ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-eth0 ... 
Sep 24 06:49:00 nbecker1 NetworkManager[24090]:    ifcfg-rh:     read connection 'System eth0'
Sep 24 06:49:00 nbecker1 NetworkManager[24090]:    ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ... 
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> found WiFi radio killswitch rfkill3 (at /sys/devices/pci0000:00/0000:00:1c.0/0000:02:00.0/ieee80211/phy0/rfkill3) (driver <unknown>)
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> found WiFi radio killswitch rfkill0 (at /sys/devices/platform/hp-wmi/rfkill/rfkill0) (driver hp-wmi)
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> WiFi enabled by radio killswitch; enabled by state file
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> WWAN enabled by radio killswitch; enabled by state file
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> WiMAX enabled by radio killswitch; enabled by state file
Sep 24 06:49:00 nbecker1 NetworkManager[24090]: <info> Networking is enabled by state file
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): driver supports SSID scans (scan_capa 0x01).
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): new 802.11 WiFi device (driver: 'iwlagn' ifindex: 3)
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/0
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): now managed
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): device state change: 1 -> 2 (reason 2)
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): bringing up device.
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): preparing device.
Sep 24 06:49:01 nbecker1 ntpd[1446]: Deleting interface #7 wlan0, fe80::213:e8ff:fed2:99e3#123, interface stats: received=0, sent=0, dropped=0, active_time=47722 secs
Sep 24 06:49:01 nbecker1 kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): deactivating device (reason: 2).
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): carrier is ON
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): new Ethernet device (driver: 'r8169' ifindex: 2)
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/1
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): now managed
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): device state change: 1 -> 2 (reason 41)
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): preparing device.
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> Activation (eth0) starting connection 'System eth0'
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): device state change: 2 -> 7 (reason 0)
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <warn> /sys/devices/virtual/net/pan0: couldn't determine device driver; ignoring...
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <warn> /sys/devices/virtual/net/vboxnet0: couldn't determine device driver; ignoring...
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> dhclient started with pid 24094
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): supplicant interface state:  starting -> ready
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (wlan0): device state change: 2 -> 3 (reason 42)
Sep 24 06:49:01 nbecker1 dhclient[24094]: Internet Systems Consortium DHCP Client 4.1.1-P1
Sep 24 06:49:01 nbecker1 dhclient[24094]: Copyright 2004-2010 Internet Systems Consortium.
Sep 24 06:49:01 nbecker1 dhclient[24094]: All rights reserved.
Sep 24 06:49:01 nbecker1 dhclient[24094]: For info, please visit https://www.isc.org/software/dhcp/
Sep 24 06:49:01 nbecker1 dhclient[24094]: 
Sep 24 06:49:01 nbecker1 NetworkManager[24090]: <info> (eth0): DHCPv4 state changed nbi -> preinit
Sep 24 06:49:01 nbecker1 dhclient[24094]: Listening on LPF/eth0/00:23:8b:53:f0:80
Sep 24 06:49:01 nbecker1 dhclient[24094]: Sending on   LPF/eth0/00:23:8b:53:f0:80
Sep 24 06:49:01 nbecker1 dhclient[24094]: Sending on   Socket/fallback
Sep 24 06:49:02 nbecker1 dhclient[24094]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Sep 24 06:49:10 nbecker1 dhclient[24094]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Sep 24 06:49:10 nbecker1 dhclient[24094]: DHCPACK from 10.32.112.3
Sep 24 06:49:10 nbecker1 dhclient[24094]: bound to 10.32.112.161 -- renewal in 41109 seconds.
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> (eth0): DHCPv4 state changed preinit -> reboot
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   address 10.32.112.161
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   prefix 24 (255.255.255.0)
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   gateway 10.32.112.1
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   nameserver '139.85.52.104'
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   nameserver '139.85.52.102'
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   nameserver '139.85.87.105'
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   nameserver '139.85.176.102'
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info>   domain name 'hughes.com'
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> (eth0): device state change: 7 -> 8 (reason 0)
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Policy set 'System eth0' (eth0) as default for IPv4 routing and DNS.
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) successful, device activated.
Sep 24 06:49:10 nbecker1 NetworkManager[24090]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.