[Pkg-utopia-maintainers] Bug#933930: Bug#933930: Bug#933930: network-manager: Ethernet connection no longer works

Vincent Lefevre vincent at vinc17.net
Wed Aug 7 10:24:52 BST 2019 

On 2019-08-06 22:24:49 +0200, Michael Biebl wrote:
> Ok, so the current state of affairs is:
> 
> dhcp=dhclient works always
> dhcp=internal (the default) fails (sometimes)
> 
> ?

That's right.

Here are more complete logs for dhcp=internal, first those
corresponding to a success, then those corresponding to a
failure.

cventin:~> journalctl -b -11 -u NetworkManager
-- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Wed 2019-08-07 11:15:01 CEST. --
Aug 06 15:00:21 cventin systemd[1]: Starting Network Manager...
Aug 06 15:00:21 cventin NetworkManager[766]: <info>  [1565096421.8155] NetworkManager (version 1.19.90) is starting... (for the first time)
Aug 06 15:00:21 cventin NetworkManager[766]: <info>  [1565096421.8156] Read config: /etc/NetworkManager/NetworkManager.conf (lib: no-mac-addr-change.conf)
Aug 06 15:00:21 cventin NetworkManager[766]: <warn>  [1565096421.8157] config: unknown key 'wifi.cloned-mac-address' in section [device-mac-addr-change-wifi] of file '/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:00:21 cventin NetworkManager[766]: <warn>  [1565096421.8157] config: unknown key 'ethernet.cloned-mac-address' in section [device-mac-addr-change-wifi] of file '/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:00:21 cventin NetworkManager[766]: <info>  [1565096421.8183] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Aug 06 15:00:21 cventin NetworkManager[766]: <info>  [1565096421.8244] manager[0x558e247f6020]: monitoring kernel firmware directory '/lib/firmware'.
Aug 06 15:00:21 cventin NetworkManager[766]: <info>  [1565096421.8245] monitoring ifupdown state file '/run/network/ifstate'.
Aug 06 15:00:23 cventin systemd[1]: Started Network Manager.
Aug 06 15:00:23 cventin NetworkManager[766]: <info>  [1565096423.8146] hostname: hostname: using hostnamed
Aug 06 15:00:23 cventin NetworkManager[766]: <info>  [1565096423.8147] hostname: hostname changed from (none) to "cventin"
Aug 06 15:00:23 cventin NetworkManager[766]: <info>  [1565096423.8153] dns-mgr[0x558e247d2240]: init: dns=default,systemd-resolved rc-manager=resolvconf
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.4806] Loaded device plugin: NMWifiFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wifi.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5546] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-bluetooth.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5610] Loaded device plugin: NMWwanFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wwan.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5843] Loaded device plugin: NMTeamFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-team.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5884] Loaded device plugin: NMAtmManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-adsl.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5887] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5889] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5891] manager: Networking is enabled by state file
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.5893] dhcp-init: Using DHCP client 'internal'
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6139] settings: Loaded settings plugin: ifupdown ("/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-settings-plugin-ifupdown.so")
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6139] settings: Loaded settings plugin: keyfile (internal)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6139] ifupdown: management mode: unmanaged
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6140] ifupdown:       interface-parser: parsing file /etc/network/interfaces
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6140] ifupdown:       interface-parser: source line includes interfaces file(s) /etc/network/interfaces.d/*
Aug 06 15:00:24 cventin NetworkManager[766]: <warn>  [1565096424.6141] ifupdown: interfaces file /etc/network/interfaces.d/* doesn't exist
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6141] ifupdown:       interface-parser: finished parsing file /etc/network/interfaces
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6479] device (lo): carrier: link connected
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6483] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6495] manager: (enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6544] settings: (enp0s25): created default wired connection 'Wired connection 2'
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.6553] device (enp0s25): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Aug 06 15:00:24 cventin NetworkManager[766]: <info>  [1565096424.8903] modem-manager: ModemManager available
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4309] device (enp0s25): carrier: link connected
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4315] device (enp0s25): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4328] policy: auto-activating connection 'Wired connection 1' (c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4340] device (enp0s25): Activation: starting connection 'Wired connection 1' (c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4342] device (enp0s25): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4348] manager: NetworkManager state is now CONNECTING
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4351] device (enp0s25): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4359] device (enp0s25): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info>  [1565096428.4365] dhcp4 (enp0s25): activation: beginning transaction (timeout in 45 seconds)
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0690] dhcp4 (enp0s25): state changed unknown -> bound
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0705] device (enp0s25): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0730] device (enp0s25): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0734] device (enp0s25): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0740] manager: NetworkManager state is now CONNECTED_LOCAL
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0755] manager: NetworkManager state is now CONNECTED_SITE
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0756] policy: set 'Wired connection 1' (enp0s25) as default for IPv4 routing and DNS
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0808] device (enp0s25): Activation: successful, device activated.
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0818] manager: NetworkManager state is now CONNECTED_GLOBAL
Aug 06 15:00:34 cventin NetworkManager[766]: <info>  [1565096434.0826] manager: startup complete
Aug 06 15:12:13 cventin NetworkManager[766]: <info>  [1565097133.8531] modem-manager: ModemManager no longer available
Aug 06 15:12:16 cventin systemd[1]: Stopping Network Manager...
Aug 06 15:12:16 cventin NetworkManager[766]: <info>  [1565097136.8430] caught SIGTERM, shutting down normally.
Aug 06 15:12:16 cventin NetworkManager[766]: <info>  [1565097136.8443] dhcp4 (enp0s25): canceled DHCP transaction
Aug 06 15:12:16 cventin NetworkManager[766]: <info>  [1565097136.8444] dhcp4 (enp0s25): state changed bound -> done
Aug 06 15:12:16 cventin NetworkManager[766]: <info>  [1565097136.8444] device (enp0s25): DHCPv4: 480 seconds grace period started
Aug 06 15:12:16 cventin NetworkManager[766]: <info>  [1565097136.8449] manager: NetworkManager state is now CONNECTED_SITE
Aug 06 15:12:16 cventin NetworkManager[766]: <info>  [1565097136.8517] exiting (success)
Aug 06 15:12:16 cventin systemd[1]: NetworkManager.service: Succeeded.
Aug 06 15:12:16 cventin systemd[1]: Stopped Network Manager.

cventin:~> journalctl -b -10 -u NetworkManager
-- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Wed 2019-08-07 11:15:01 CEST. --
Aug 06 15:12:53 cventin systemd[1]: Starting Network Manager...
Aug 06 15:12:54 cventin NetworkManager[807]: <info>  [1565097174.0730] NetworkManager (version 1.19.90) is starting... (for the first time)
Aug 06 15:12:54 cventin NetworkManager[807]: <info>  [1565097174.0731] Read config: /etc/NetworkManager/NetworkManager.conf (lib: no-mac-addr-change.conf)
Aug 06 15:12:54 cventin NetworkManager[807]: <warn>  [1565097174.0732] config: unknown key 'wifi.cloned-mac-address' in section [device-mac-addr-change-wifi] of file '/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:12:54 cventin NetworkManager[807]: <warn>  [1565097174.0732] config: unknown key 'ethernet.cloned-mac-address' in section [device-mac-addr-change-wifi] of file '/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:12:54 cventin NetworkManager[807]: <info>  [1565097174.0769] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Aug 06 15:12:54 cventin NetworkManager[807]: <info>  [1565097174.0823] manager[0x55d6af5ac020]: monitoring kernel firmware directory '/lib/firmware'.
Aug 06 15:12:54 cventin NetworkManager[807]: <info>  [1565097174.0823] monitoring ifupdown state file '/run/network/ifstate'.
Aug 06 15:12:54 cventin systemd[1]: Started Network Manager.
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7226] hostname: hostname: using hostnamed
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7226] hostname: hostname changed from (none) to "cventin"
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7232] dns-mgr[0x55d6af589240]: init: dns=default,systemd-resolved rc-manager=resolvconf
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7328] Loaded device plugin: NMWifiFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wifi.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7396] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-bluetooth.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7406] Loaded device plugin: NMWwanFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wwan.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7436] Loaded device plugin: NMTeamFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-team.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7446] Loaded device plugin: NMAtmManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-adsl.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7449] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7450] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7451] manager: Networking is enabled by state file
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7453] dhcp-init: Using DHCP client 'internal'
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7466] settings: Loaded settings plugin: ifupdown ("/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-settings-plugin-ifupdown.so")
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7466] settings: Loaded settings plugin: keyfile (internal)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7466] ifupdown: management mode: unmanaged
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7467] ifupdown:       interface-parser: parsing file /etc/network/interfaces
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7467] ifupdown:       interface-parser: source line includes interfaces file(s) /etc/network/interfaces.d/*
Aug 06 15:12:55 cventin NetworkManager[807]: <warn>  [1565097175.7467] ifupdown: interfaces file /etc/network/interfaces.d/* doesn't exist
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7468] ifupdown:       interface-parser: finished parsing file /etc/network/interfaces
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7517] device (lo): carrier: link connected
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7521] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7532] manager: (enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7565] settings: (enp0s25): created default wired connection 'Wired connection 2'
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.7572] device (enp0s25): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Aug 06 15:12:55 cventin NetworkManager[807]: <info>  [1565097175.9889] modem-manager: ModemManager available
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5367] device (enp0s25): carrier: link connected
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5375] device (enp0s25): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5393] policy: auto-activating connection 'Wired connection 1' (c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5407] device (enp0s25): Activation: starting connection 'Wired connection 1' (c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5410] device (enp0s25): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5419] manager: NetworkManager state is now CONNECTING
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5424] device (enp0s25): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5434] device (enp0s25): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info>  [1565097179.5441] dhcp4 (enp0s25): activation: beginning transaction (timeout in 45 seconds)
Aug 06 15:13:05 cventin NetworkManager[807]: <info>  [1565097185.2693] dhcp4 (enp0s25): state changed unknown -> expire
Aug 06 15:14:04 cventin NetworkManager[807]: <info>  [1565097244.3113] modem-manager: ModemManager no longer available
Aug 06 15:14:06 cventin systemd[1]: Stopping Network Manager...
Aug 06 15:14:06 cventin NetworkManager[807]: <info>  [1565097246.3392] caught SIGTERM, shutting down normally.
Aug 06 15:14:06 cventin NetworkManager[807]: <info>  [1565097246.3655] dhcp4 (enp0s25): canceled DHCP transaction
Aug 06 15:14:06 cventin NetworkManager[807]: <info>  [1565097246.3655] dhcp4 (enp0s25): state changed expire -> done
Aug 06 15:14:06 cventin NetworkManager[807]: <info>  [1565097246.3656] dhcp4 (enp0s25): canceled DHCP transaction
Aug 06 15:14:06 cventin NetworkManager[807]: <info>  [1565097246.3665] manager: startup complete
Aug 06 15:14:06 cventin NetworkManager[807]: <info>  [1565097246.3732] exiting (success)
Aug 06 15:14:06 cventin systemd[1]: NetworkManager.service: Succeeded.
Aug 06 15:14:06 cventin systemd[1]: Stopped Network Manager.

The first difference is: "state changed unknown -> bound" in the first
case, "state changed unknown -> expire" in the second case.

With dhclient instead of internal, one has:

[...]
Aug 06 15:48:15 cventin NetworkManager[797]: <info>  [1565099295.6037] dhcp4 (enp0s25): dhclient started with pid 1052
Aug 06 15:48:15 cventin dhclient[1052]: DHCPREQUEST for 140.77.13.17 on enp0s25 to 255.255.255.255 port 67
Aug 06 15:48:21 cventin dhclient[1052]: DHCPREQUEST for 140.77.13.17 on enp0s25 to 255.255.255.255 port 67
Aug 06 15:48:21 cventin dhclient[1052]: DHCPNAK from 10.0.1.1
Aug 06 15:48:21 cventin NetworkManager[797]: <info>  [1565099301.7956] dhcp4 (enp0s25): state changed unknown -> expire
Aug 06 15:48:21 cventin NetworkManager[797]: <info>  [1565099301.8037] dhcp4 (enp0s25): state changed expire -> unknown
Aug 06 15:48:21 cventin dhclient[1052]: DHCPDISCOVER on enp0s25 to 255.255.255.255 port 67 interval 4
Aug 06 15:48:21 cventin dhclient[1052]: DHCPOFFER of 140.77.13.17 from 140.77.1.12
Aug 06 15:48:21 cventin dhclient[1052]: DHCPREQUEST for 140.77.13.17 on enp0s25 to 255.255.255.255 port 67
Aug 06 15:48:21 cventin dhclient[1052]: DHCPACK of 140.77.13.17 from 140.77.1.12
Aug 06 15:48:21 cventin NetworkManager[797]: <info>  [1565099301.8160] dhcp4 (enp0s25):   address 140.77.13.17
[...]

-- 
Vincent Lefèvre <vincent at vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)

More information about the Pkg-utopia-maintainers mailing list