#757470 network-manager: after resume from suspend, fails to start dhclient on wired interface

Package:
network-manager
Source:
network-manager
Description:
network management framework (daemon and userspace tools)
Submitter:
Zack Weinberg
Date:
2018-12-14 05:21:06 UTC
Severity:
normal
#757470#5
Date:
2014-08-08 15:13:31 UTC
From:
To:
Upon resume from suspend on one particular computer, network-manager fails to
bring up the wired interface, with these error messages in /var/log/daemon.log:

Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) starting
connection 'Wired connection 1'
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) scheduled...
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) started...
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): device state change:
disconnected -> prepare (reason 'none') [30 40 0]
Aug  8 10:51:38 othila NetworkManager[716]: <info> NetworkManager state is now
CONNECTING
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) scheduled...
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) complete.
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) starting...
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): device state change:
prepare -> config (reason 'none') [40 50 0]
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) successful.
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) scheduled.
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) complete.
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) started...
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): device state change:
config -> ip-config (reason 'none') [50 70 0]
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Beginning
DHCPv4 transaction (timeout in 45 seconds)
Aug  8 10:51:38 othila NetworkManager[716]: <info> dhclient started with pid
23723
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) complete.
Aug  8 10:51:38 othila dhclient: Internet Systems Consortium DHCP Client 4.3.0
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): DHCPv4 client pid
23723 exited with status -1
Aug  8 10:51:38 othila NetworkManager[716]: <warn> DHCP client died abnormally
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 4 of
5 (IPv4 Configure Timeout) scheduled...
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 4 of
5 (IPv4 Configure Timeout) started...
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): device state change:
ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Aug  8 10:51:38 othila NetworkManager[716]: <info> NetworkManager state is now
DISCONNECTED
Aug  8 10:51:38 othila NetworkManager[716]: <info> Disabling autoconnect for
connection 'Wired connection 1'.
Aug  8 10:51:38 othila NetworkManager[716]: <warn> Activation (eth0) failed for
connection 'Wired connection 1'
Aug  8 10:51:38 othila NetworkManager[716]: <info> Activation (eth0) Stage 4 of
5 (IPv4 Configure Timeout) complete.
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): device state change:
failed -> disconnected (reason 'none') [120 30 0]
Aug  8 10:51:38 othila NetworkManager[716]: <info> (eth0): deactivating device
(reason 'none') [0]

If, as root, I manually invoke 'dhclient eth0', that works fine, and network-
manager notices that the interface has been brought up:

Aug  8 10:52:57 othila dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 8
Aug  8 10:52:57 othila dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Aug  8 10:52:57 othila dhclient: DHCPOFFER from 128.2.142.1
Aug  8 10:52:57 othila dhclient: DHCPACK from 128.2.142.1
Aug  8 10:52:57 othila avahi-daemon[701]: Joining mDNS multicast group on
interface eth0.IPv4 with address 128.2.142.99.
Aug  8 10:52:57 othila avahi-daemon[701]: New relevant interface eth0.IPv4 for
mDNS.
Aug  8 10:52:57 othila avahi-daemon[701]: Registering new address record for
128.2.142.99 on eth0.IPv4.
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) starting
connection 'eth0'
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) scheduled...
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) started...
Aug  8 10:52:57 othila NetworkManager[716]: <info> (eth0): device state change:
disconnected -> prepare (reason 'none') [30 40 0]
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) scheduled...
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) complete.
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) starting...
Aug  8 10:52:57 othila NetworkManager[716]: <info> (eth0): device state change:
prepare -> config (reason 'none') [40 50 0]
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) successful.
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) scheduled.
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) complete.
Aug  8 10:52:57 othila dhclient: bound to 128.2.142.99 -- renewal in 211543
seconds.
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 5 of
5 (IPv4 Commit) started...
Aug  8 10:52:57 othila NetworkManager[716]: <warn> Could not send ARP for local
address 128.2.142.99: Failed to execute child process "/sbin/arp
ing" (No such file or directory)
Aug  8 10:52:57 othila NetworkManager[716]: <info> (eth0): device state change:
ip-config -> ip-check (reason 'none') [70 80 0]
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0) Stage 5 of
5 (IPv4 Commit) complete.
Aug  8 10:52:57 othila NetworkManager[716]: <info> (eth0): device state change:
ip-check -> secondaries (reason 'none') [80 90 0]
Aug  8 10:52:57 othila NetworkManager[716]: <info> (eth0): device state change:
secondaries -> activated (reason 'none') [90 100 0]
Aug  8 10:52:57 othila NetworkManager[716]: <info> NetworkManager state is now
CONNECTED_LOCAL
Aug  8 10:52:57 othila NetworkManager[716]: <info> NetworkManager state is now
CONNECTED_GLOBAL
Aug  8 10:52:57 othila NetworkManager[716]: <info> Policy set 'eth0' (eth0) as
default for IPv4 routing and DNS.
Aug  8 10:52:57 othila NetworkManager[716]: <info> Activation (eth0)
successful, device activated.

so that looks awfully like n-m is invoking dhclient incorrectly, but I can't
find anything else in the logs to indicate what it did wrong.  Note that this
*only* happens on resume from suspend; on a cold boot, it works fine:

Aug  5 13:24:48 othila NetworkManager[763]: <info> (eth0): link connected
Aug  5 13:24:48 othila NetworkManager[763]: <info> (eth0): device state change:
unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Aug  5 13:24:48 othila NetworkManager[763]: <info> Auto-activating connection
'Wired connection 1'.
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) starting
connection 'Wired connection 1'
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) scheduled...
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) started...
Aug  5 13:24:48 othila NetworkManager[763]: <info> (eth0): device state change:
disconnected -> prepare (reason 'none') [30 40 0]
Aug  5 13:24:48 othila NetworkManager[763]: <info> NetworkManager state is now
CONNECTING
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) scheduled...
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 1 of
5 (Device Prepare) complete.
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) starting...
Aug  5 13:24:48 othila NetworkManager[763]: <info> (eth0): device state change:
prepare -> config (reason 'none') [40 50 0]
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) successful.
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) scheduled.
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 2 of
5 (Device Configure) complete.
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) started...
Aug  5 13:24:48 othila NetworkManager[763]: <info> (eth0): device state change:
config -> ip-config (reason 'none') [50 70 0]
Aug  5 13:24:48 othila NetworkManager[763]: <info> Activation (eth0) Beginning
DHCPv4 transaction (timeout in 45 seconds)
Aug  5 13:24:49 othila NetworkManager[763]: <info> dhclient started with pid
910
Aug  5 13:24:49 othila NetworkManager[763]: <warn> Unable to detect kernel
support for extended IFA_FLAGS. Assume no kernel support.
Aug  5 13:24:49 othila NetworkManager[763]: <info> Activation (eth0) Stage 3 of
5 (IP Configure Start) complete.
Aug  5 13:24:49 othila dhclient: Internet Systems Consortium DHCP Client 4.3.0
Aug  5 13:24:49 othila dhclient: Copyright 2004-2014 Internet Systems
Consortium.
Aug  5 13:24:49 othila dhclient: All rights reserved.
Aug  5 13:24:49 othila dhclient: For info, please visit
https://www.isc.org/software/dhcp/
Aug  5 13:24:49 othila dhclient:
Aug  5 13:24:49 othila NetworkManager[763]: Internet Systems Consortium DHCP
Client 4.3.0
Aug  5 13:24:49 othila NetworkManager[763]: Copyright 2004-2014 Internet
Systems Consortium.
Aug  5 13:24:49 othila NetworkManager[763]: All rights reserved.
Aug  5 13:24:49 othila NetworkManager[763]: For info, please visit
https://www.isc.org/software/dhcp/
Aug  5 13:24:49 othila NetworkManager[763]: <info> (eth0): DHCPv4 state changed
nbi -> preinit
Aug  5 13:24:49 othila dhclient: Listening on LPF/eth0/e8:9a:8f:d5:ea:d7
Aug  5 13:24:49 othila dhclient: Sending on   LPF/eth0/e8:9a:8f:d5:ea:d7
Aug  5 13:24:49 othila dhclient: Sending on   LPF/eth0/e8:9a:8f:d5:ea:d7
Aug  5 13:24:49 othila dhclient: Sending on   Socket/fallback
Aug  5 13:24:49 othila dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 7
Aug  5 13:24:49 othila NetworkManager[763]: Listening on
LPF/eth0/e8:9a:8f:d5:ea:d7
Aug  5 13:24:49 othila NetworkManager[763]: Sending on
LPF/eth0/e8:9a:8f:d5:ea:d7
Aug  5 13:24:49 othila NetworkManager[763]: Sending on   Socket/fallback
Aug  5 13:24:49 othila NetworkManager[763]: DHCPDISCOVER on eth0 to
255.255.255.255 port 67 interval 7
Aug  5 13:25:19 othila dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 14
Aug  5 13:25:19 othila NetworkManager[763]: DHCPDISCOVER on eth0 to
255.255.255.255 port 67 interval 14
Aug  5 13:25:19 othila dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Aug  5 13:25:19 othila dhclient: DHCPOFFER from 128.2.142.1
Aug  5 13:25:19 othila NetworkManager[763]: DHCPREQUEST on eth0 to
255.255.255.255 port 67
Aug  5 13:25:19 othila NetworkManager[763]: DHCPOFFER from 128.2.142.1
Aug  5 13:25:19 othila dhclient: DHCPACK from 128.2.142.1
Aug  5 13:25:19 othila NetworkManager[763]: DHCPACK from 128.2.142.1
Aug  5 13:25:19 othila dhclient: bound to 128.2.142.99 -- renewal in 213442
seconds.
Aug  5 13:25:19 othila NetworkManager[763]: <info> (eth0): DHCPv4 state changed
preinit -> bound
Aug  5 13:25:19 othila NetworkManager[763]: <info>   address 128.2.142.99
Aug  5 13:25:19 othila NetworkManager[763]: <info>   plen 24 (255.255.255.0)
Aug  5 13:25:19 othila NetworkManager[763]: <info>   gateway 128.2.142.1
Aug  5 13:25:19 othila NetworkManager[763]: <info>   server identifier
128.2.136.32
Aug  5 13:25:19 othila NetworkManager[763]: <info>   lease time 432000
Aug  5 13:25:19 othila NetworkManager[763]: <info>   hostname
'othila.ece.cmu.edu'
Aug  5 13:25:19 othila NetworkManager[763]: <info>   nameserver '128.2.136.10'
Aug  5 13:25:19 othila NetworkManager[763]: <info>   nameserver '128.2.136.71'
Aug  5 13:25:19 othila NetworkManager[763]: <info>   nameserver '128.2.129.21'
Aug  5 13:25:19 othila NetworkManager[763]: <info>   domain name 'ece.cmu.edu'
Aug  5 13:25:19 othila NetworkManager[763]: <info> Activation (eth0) Stage 5 of
5 (IPv4 Configure Commit) scheduled...
Aug  5 13:25:19 othila NetworkManager[763]: <info> Activation (eth0) Stage 5 of
5 (IPv4 Commit) started...
Aug  5 13:25:19 othila avahi-daemon[721]: Joining mDNS multicast group on
interface eth0.IPv4 with address 128.2.142.99.
Aug  5 13:25:19 othila avahi-daemon[721]: New relevant interface eth0.IPv4 for
mDNS.
Aug  5 13:25:19 othila avahi-daemon[721]: Registering new address record for
128.2.142.99 on eth0.IPv4.
Aug  5 13:25:19 othila NetworkManager[763]: <info> (eth0): device state change:
ip-config -> ip-check (reason 'none') [70 80 0]
Aug  5 13:25:19 othila NetworkManager[763]: <info> Activation (eth0) Stage 5 of
5 (IPv4 Commit) complete.
Aug  5 13:25:19 othila NetworkManager[763]: <info> (eth0): device state change:
ip-check -> secondaries (reason 'none') [80 90 0]
Aug  5 13:25:19 othila NetworkManager[763]: bound to 128.2.142.99 -- renewal in
213442 seconds.
Aug  5 13:25:19 othila NetworkManager[763]: <info> (eth0): device state change:
secondaries -> activated (reason 'none') [90 100 0]
Aug  5 13:25:19 othila NetworkManager[763]: <info> NetworkManager state is now
CONNECTED_LOCAL
Aug  5 13:25:19 othila NetworkManager[763]: <info> NetworkManager state is now
CONNECTED_GLOBAL
Aug  5 13:25:19 othila NetworkManager[763]: <info> Policy set 'Wired connection
1' (eth0) as default for IPv4 routing and DNS.
Aug  5 13:25:19 othila NetworkManager[763]: <info> Activation (eth0)
successful, device activated.
Aug  5 13:25:19 othila NetworkManager[763]: <info> startup complete
#757470#10
Date:
2014-10-06 09:37:54 UTC
From:
To:
I can confirm the same behviour with identical log on my laptop.

My network-manager 0.9.10.0-2,

cat /etc/NetworkManager/NetworkManager.conf
[main]
plugins=ifupdown,keyfile

[ifupdown]
managed=false

[keyfile]
unmanaged-devices=interface-name:docker0
#757470#15
Date:
2018-12-14 05:18:19 UTC
From:
To:
When system auto suspends via Gnome power manager and then is resumed the network interface
comes back up but has no address. Looks like Network Manager fails to renew the addres.

Partial log:
Dec  9 20:26:22 xeon-e3 kernel: [20711.261552] ACPI: Waking up from system sleep state S3

Dec  9 20:26:22 xeon-e3 kernel: [20712.684611] ixgbe 0000:04:00.0: Multiqueue Enabled: Rx Queue count = 12, Tx Queue count = 12 XDP Queue count = 0
Dec  9 20:26:22 xeon-e3 kernel: [20712.959613] usb 2-9: reset high-speed USB device number 2 using xhci_hcd
Dec  9 20:26:22 xeon-e3 kernel: [20713.235765] usb 3-5: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
Dec  9 20:26:22 xeon-e3 kernel: [20713.299603] [drm] ib test on ring 5 succeeded
Dec  9 20:26:22 xeon-e3 kernel: [20713.335609] usb 2-10.4: reset high-speed USB device number 5 using xhci_hcd
Dec  9 20:26:22 xeon-e3 kernel: [20713.515620] usb 2-10.2: reset full-speed USB device number 8 using xhci_hcd
Dec  9 20:26:22 xeon-e3 kernel: [20713.731622] usb 2-10.4.4: reset full-speed USB device number 6 using xhci_hcd
Dec  9 20:26:22 xeon-e3 kernel: [20714.147621] usb 2-10.4.4.1: reset full-speed USB device number 7 using xhci_hcd
Dec  9 20:26:22 xeon-e3 kernel: [20714.207573] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Dec  9 20:26:22 xeon-e3 kernel: [20714.328261] ata2.00: configured for UDMA/133
Dec  9 20:26:22 xeon-e3 kernel: [20714.344237] OOM killer enabled.
Dec  9 20:26:22 xeon-e3 kernel: [20714.344239] Restarting tasks ... done.
Dec  9 20:26:22 xeon-e3 kernel: [20714.360230] PM: suspend exit
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.1278] device (enp12s0): state change: disconnected -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.1942] manager: sleep: wake requested (sleeping: yes  enabled: yes)
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.1943] device (eno1): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec  9 20:26:22 xeon-e3 kernel: [20714.532995] e1000e: eno1 NIC Link is Down
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.3157] device (enp12s0): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.3457] device (eno1): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dec  9 20:26:22 xeon-e3 kernel: [20714.564522] IPv6: ADDRCONF(NETDEV_UP): eno1: link is not ready
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.5866] device (enp12s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dec  9 20:26:22 xeon-e3 kernel: [20714.803738] IPv6: ADDRCONF(NETDEV_UP): eno1: link is not ready
Dec  9 20:26:22 xeon-e3 kernel: [20714.805578] IPv6: ADDRCONF(NETDEV_UP): enp12s0: link is not ready
Dec  9 20:26:22 xeon-e3 NetworkManager[981]: <info>  [1544415982.6112] device (ens4): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dec  9 20:26:22 xeon-e3 kernel: [20714.828119] IPv6: ADDRCONF(NETDEV_UP): enp12s0: link is not ready
Dec  9 20:26:22 xeon-e3 kernel: [20714.830112] IPv6: ADDRCONF(NETDEV_UP): ens4: link is not ready
Dec  9 20:26:22 xeon-e3 kernel: [20714.891741] IPv6: ADDRCONF(NETDEV_UP): ens4: link is not ready
Dec  9 20:26:25 xeon-e3 kernel: [20717.780117] igb 0000:0c:00.0 enp12s0: igb: enp12s0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Dec  9 20:26:25 xeon-e3 NetworkManager[981]: <info>  [1544415985.6705] device (enp12s0): carrier: link connected
Dec  9 20:26:25 xeon-e3 NetworkManager[981]: <info>  [1544415985.6708] device (enp12s0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Dec  9 20:26:25 xeon-e3 kernel: [20717.887814] IPv6: ADDRCONF(NETDEV_CHANGE): enp12s0: link becomes ready
Dec  9 20:28:37 xeon-e3 NetworkManager[981]: <info>  [1544416117.5657] agent-manager: req[0x7fa62c0028b0, :1.227/org.gnome.Shell.NetworkAgent/1000]: agent registered