Discussion:
Bug#933930: network-manager: Ethernet connection no longer works
Add Reply
Vincent Lefevre
2019-08-05 10:30:01 UTC
Reply
Permalink
1.18.0-3 is also working.

cventin:~> journalctl -b -g network
-- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Mon 2019-08-05 12:21:38 CEST. --
Aug 05 12:05:44 cventin kernel: e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
Aug 05 12:05:44 cventin kernel: e1000e 0000:00:19.0 eth0: Intel(R) PRO/1000 Network Connection
Aug 05 12:05:44 cventin ifup[456]: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-pre-up.d/ethtool
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
Aug 05 12:05:44 cventin ifup[456]: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-pre-up.d/ethtool
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
Aug 05 12:05:44 cventin ifup[456]: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/avahi-daemon
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/ethtool
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/mountnfs
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/wpasupplicant
Aug 05 12:05:44 cventin ifup[456]: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/avahi-daemon
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/ethtool
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/mountnfs
Aug 05 12:05:44 cventin ifup[456]: run-parts: executing /etc/network/if-up.d/wpasupplicant
Aug 05 12:05:45 cventin systemd[1]: Starting Network Time Synchronization...
Aug 05 12:05:46 cventin systemd[1]: Started Network Time Synchronization.
Aug 05 12:05:46 cventin systemd[1]: Starting Network Manager...
Aug 05 12:05:46 cventin NetworkManager[758]: <info> [1564999546.7164] NetworkManager (version 1.18.0) is starting... (for the first time)
Aug 05 12:05:46 cventin NetworkManager[758]: <info> [1564999546.7166] Read config: /etc/NetworkManager/NetworkManager.conf (lib: no-mac-addr-change.conf)
Aug 05 12:05:46 cventin NetworkManager[758]: <warn> [1564999546.7166] 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 05 12:05:46 cventin NetworkManager[758]: <warn> [1564999546.7166] 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 05 12:05:46 cventin NetworkManager[758]: <info> [1564999546.7221] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Aug 05 12:05:46 cventin NetworkManager[758]: <info> [1564999546.7239] monitoring ifupdown state file '/run/network/ifstate'.
Aug 05 12:05:46 cventin dbus-daemon[753]: [system] Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.4' (uid=0 pid=758 comm="/usr/sbin/NetworkManager --no-daemon ")
Aug 05 12:05:47 cventin avahi-daemon[787]: Network interface enumeration completed.
Aug 05 12:05:47 cventin systemd[1]: Started Network Manager.
Aug 05 12:05:47 cventin systemd[1]: Starting Network Manager Wait Online...
Aug 05 12:05:47 cventin systemd[1]: Reached target Network.
Aug 05 12:05:48 cventin dbus-daemon[753]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.4' (uid=0 pid=758 comm="/usr/sbin/NetworkManager --no-daemon ")
Aug 05 12:05:48 cventin systemd[1]: Starting Network Manager Script Dispatcher Service...
Aug 05 12:05:48 cventin systemd[1]: Started Network Manager Script Dispatcher Service.
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2743] ifupdown: interface-parser: parsing file /etc/network/interfaces
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2744] ifupdown: interface-parser: source line includes interfaces file(s) /etc/network/interfaces.d/*
Aug 05 12:05:48 cventin NetworkManager[758]: <warn> [1564999548.2744] ifupdown: interfaces file /etc/network/interfaces.d/* doesn't exist
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2745] ifupdown: interface-parser: finished parsing file /etc/network/interfaces
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2745] settings: Loaded settings plugin: SettingsPluginIfupdown ("/usr/lib/x86_64-linux-gnu/NetworkManager/1.18.0/libnm-settings-plugin-ifupdown.so")
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2774] keyfile: new connection /etc/NetworkManager/system-connections/Wired connection 1 (c89d3bc3-8d9e-44f8-ac86-7e6884d08219,"Wired connection 1")
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2783] manager: Networking is enabled by state file
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2810] Loaded device plugin: NMWifiFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.18.0/libnm-device-plugin-wifi.so)
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2860] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.18.0/libnm-device-plugin-bluetooth.so)
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2868] Loaded device plugin: NMWwanFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.18.0/libnm-device-plugin-wwan.so)
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2898] Loaded device plugin: NMTeamFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.18.0/libnm-device-plugin-team.so)
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2907] Loaded device plugin: NMAtmManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.18.0/libnm-device-plugin-adsl.so)
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2922] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Aug 05 12:05:48 cventin NetworkManager[758]: <info> [1564999548.2934] manager: (enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Aug 05 12:05:50 cventin systemd[987]: Listening on GnuPG network certificate management daemon.
Aug 05 12:05:52 cventin NetworkManager[758]: <info> [1564999552.2016] manager: NetworkManager state is now CONNECTING
Aug 05 12:05:55 cventin systemd[1048]: Listening on GnuPG network certificate management daemon.
Aug 05 12:05:58 cventin systemd[1]: NetworkManager-dispatcher.service: Succeeded.
Aug 05 12:05:58 cventin NetworkManager[758]: <info> [1564999558.5645] manager: NetworkManager state is now CONNECTED_LOCAL
Aug 05 12:05:58 cventin NetworkManager[758]: <info> [1564999558.5694] manager: NetworkManager state is now CONNECTED_SITE
Aug 05 12:05:58 cventin dbus-daemon[753]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.4' (uid=0 pid=758 comm="/usr/sbin/NetworkManager --no-daemon ")
Aug 05 12:05:58 cventin NetworkManager[758]: <info> [1564999558.5753] manager: NetworkManager state is now CONNECTED_GLOBAL
Aug 05 12:05:58 cventin dbus-daemon[753]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.4' (uid=0 pid=758 comm="/usr/sbin/NetworkManager --no-daemon ")
Aug 05 12:05:58 cventin systemd[1]: Started Network Manager Wait Online.
Aug 05 12:05:58 cventin systemd[1]: Reached target Network is Online.
Aug 05 12:05:58 cventin systemd[1]: Starting Network Manager Script Dispatcher Service...
Aug 05 12:05:58 cventin systemd[1]: Started Network Manager Script Dispatcher Service.
Aug 05 12:06:06 cventin systemd[987]: Closed GnuPG network certificate management daemon.
Aug 05 12:06:09 cventin systemd[1]: NetworkManager-dispatcher.service: Succeeded.
--
Vincent Lefèvre <***@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)
Michael Biebl
2019-08-06 09:10:02 UTC
Reply
Permalink
Control: tags -1 + moreinfo

Can you try and switch to dhclient instead of the internal one.


$ cat /etc/NetworkManager/conf.d/dhcp.conf
[main]
dhcp=dhclient
--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?
Vincent Lefevre
2019-08-06 13:40:01 UTC
Reply
Permalink
Post by Michael Biebl
Can you try and switch to dhclient instead of the internal one.
$ cat /etc/NetworkManager/conf.d/dhcp.conf
[main]
dhcp=dhclient
I upgraded to 1.19.90-2 again, and I did that, and rebooted,
and it worked.

Then, to be sure, I removed dhcp.conf and rebooted, and...
it worked!

Then I rebooted again, and I got a failure.

So, this is not always reproducible.

FYI, a diff of the logs for 1.19.90-2 (with date-information removed
for the diff) between working connection and failure.

--- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Tue 2019-08-06 15:01:18 CEST. --
+-- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Tue 2019-08-06 15:13:18 CEST. --
cventin kernel: e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
cventin kernel: e1000e 0000:00:19.0 eth0: Intel(R) PRO/1000 Network Connection
cventin ifup: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
cventin ifup: run-parts: executing /etc/network/if-pre-up.d/ethtool
cventin ifup: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
cventin ifup: /bin/run-parts --exit-on-error --verbose /etc/network/if-pre-up.d
cventin ifup: run-parts: executing /etc/network/if-pre-up.d/ethtool
cventin ifup: run-parts: executing /etc/network/if-pre-up.d/wpasupplicant
cventin ifup: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
cventin ifup: run-parts: executing /etc/network/if-up.d/avahi-daemon
cventin ifup: run-parts: executing /etc/network/if-up.d/ethtool
cventin ifup: run-parts: executing /etc/network/if-up.d/mountnfs
cventin ifup: run-parts: executing /etc/network/if-up.d/wpasupplicant
cventin ifup: /bin/run-parts --exit-on-error --verbose /etc/network/if-up.d
cventin ifup: run-parts: executing /etc/network/if-up.d/avahi-daemon
cventin ifup: run-parts: executing /etc/network/if-up.d/ethtool
cventin ifup: run-parts: executing /etc/network/if-up.d/mountnfs
cventin ifup: run-parts: executing /etc/network/if-up.d/wpasupplicant
cventin systemd: Starting Network Time Synchronization...
cventin systemd: Started Network Time Synchronization.
cventin systemd: Starting Network Manager...
cventin NetworkManager: <info> NetworkManager (version 1.19.90) is starting... (for the first time)
cventin NetworkManager: <info> Read config: /etc/NetworkManager/NetworkManager.conf (lib: no-mac-addr-change.conf)
cventin NetworkManager: <warn> 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'
cventin NetworkManager: <warn> 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'
cventin NetworkManager: <info> bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
cventin NetworkManager: <info> monitoring ifupdown state file '/run/network/ifstate'.
-cventin dbus-daemon: Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=766 comm="/usr/sbin/NetworkManager --no-daemon ")
+cventin dbus-daemon: Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.7' (uid=0 pid=807 comm="/usr/sbin/NetworkManager --no-daemon ")
cventin avahi-daemon: Network interface enumeration completed.
cventin systemd: Started Network Manager.
cventin systemd: Starting Network Manager Wait Online...
cventin systemd: Reached target Network.
cventin NetworkManager: <info> Loaded device plugin: NMWifiFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wifi.so)
cventin NetworkManager: <info> Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-bluetooth.so)
cventin NetworkManager: <info> Loaded device plugin: NMWwanFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wwan.so)
cventin NetworkManager: <info> Loaded device plugin: NMTeamFactory (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-team.so)
cventin NetworkManager: <info> Loaded device plugin: NMAtmManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-adsl.so)
cventin NetworkManager: <info> manager: Networking is enabled by state file
-cventin dbus-daemon: Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.5' (uid=0 pid=766 comm="/usr/sbin/NetworkManager --no-daemon ")
+cventin dbus-daemon: Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=807 comm="/usr/sbin/NetworkManager --no-daemon ")
cventin NetworkManager: <info> settings: Loaded settings plugin: ifupdown ("/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-settings-plugin-ifupdown.so")
-cventin systemd: Starting Network Manager Script Dispatcher Service...
cventin NetworkManager: <info> ifupdown: interface-parser: parsing file /etc/network/interfaces
cventin NetworkManager: <info> ifupdown: interface-parser: source line includes interfaces file(s) /etc/network/interfaces.d/*
cventin NetworkManager: <warn> ifupdown: interfaces file /etc/network/interfaces.d/* doesn't exist
cventin NetworkManager: <info> ifupdown: interface-parser: finished parsing file /etc/network/interfaces
cventin NetworkManager: <info> manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
-cventin systemd: Started Network Manager Script Dispatcher Service.
cventin NetworkManager: <info> manager: (enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
+cventin systemd: Starting Network Manager Script Dispatcher Service...
+cventin systemd: Started Network Manager Script Dispatcher Service.
cventin systemd: Listening on GnuPG network certificate management daemon.
cventin NetworkManager: <info> manager: NetworkManager state is now CONNECTING
cventin systemd: Listening on GnuPG network certificate management daemon.
-cventin NetworkManager: <info> manager: NetworkManager state is now CONNECTED_LOCAL
-cventin NetworkManager: <info> manager: NetworkManager state is now CONNECTED_SITE
-cventin dbus-daemon: Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.5' (uid=0 pid=766 comm="/usr/sbin/NetworkManager --no-daemon ")
-cventin NetworkManager: <info> manager: NetworkManager state is now CONNECTED_GLOBAL
-cventin systemd: Started Network Manager Wait Online.
-cventin systemd: Reached target Network is Online.
-cventin systemd: Closed GnuPG network certificate management daemon.
cventin systemd: NetworkManager-dispatcher.service: Succeeded.
+cventin systemd: Closed GnuPG network certificate management daemon.

Now, I'll try to see if I can reproduce the failure with dhcp.conf.
--
Vincent Lefèvre <***@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)
Vincent Lefevre
2019-08-07 09:30:02 UTC
Reply
Permalink
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 <***@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)
Vincent Lefevre
2019-08-07 14:10:01 UTC
Reply
Permalink
<thaller> mbiebl_, Unclear what is not working. Could you ask for
level=TRACE logs? See
https://cgit.freedesktop.org/NetworkManager/NetworkManager/tree/contrib/fedora/rpm/NetworkManager.conf#n28
, preferably without ratelimiting from journal (see also the comment)
I've attached an archive with 3 log files of tests with the
internal dhcp client:

* nm-1.19.90-failing (with network-manager 1.19.90-2).
I had to wait for more that one minute to get an IP address, and this
was not even the correct one (I normally have a fixed IP address).
Sometimes, this is worse, e.g. after each of the following reboots
REBOOT in 1s
REBOOT in 2s
REBOOT in 4s
REBOOT in 8s
REBOOT in 16s
REBOOT in 32s
REBOOT in 1min 4s
I got "NAK: requested address not available". I did not wait longer.

* nm-1.19.90-working (with network-manager 1.19.90-2).
I got the correct IP address (140.77.13.17) after 5 seconds.
This is OK.

* nm-1.20.0-failing (with network-manager 1.20.0-1).
After each of the following reboots
REBOOT in 1s
REBOOT in 2s
REBOOT in 4s
REBOOT in 8s
REBOOT in 16s
REBOOT in 32s
REBOOT in 1min 4s
I got "NAK: requested address not available". I did not wait longer.
I tried several times and could not make it work.
Still no issues with dhcp=dhclient.
--
Vincent Lefèvre <***@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)
Vincent Lefevre
2019-08-08 16:10:01 UTC
Reply
Permalink
Bringing Vincent into the loop here.
Vincent, can you gather the information Beniamino is asking for?
Would it be possible to capture a dump of DHCP packets for a success
and for a failure?
Each time after DHCP Request, there are 1 NAK packet (from 10.0.1.1)
and 2 NAK packets (from 140.77.1.11 and 140.77.1.12), but not always
in the same order.

With the internal DHCP client, this seems to be a success only if an
ACK packet comes first. There is no such issue with the external one.

Do you need more information?
--
Vincent Lefèvre <***@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)
Beniamino Galvani
2019-08-09 08:00:01 UTC
Reply
Permalink
Post by Vincent Lefevre
Bringing Vincent into the loop here.
Vincent, can you gather the information Beniamino is asking for?
Would it be possible to capture a dump of DHCP packets for a success
and for a failure?
Each time after DHCP Request, there are 1 NAK packet (from 10.0.1.1)
and 2 NAK packets (from 140.77.1.11 and 140.77.1.12), but not always
in the same order.
With the internal DHCP client, this seems to be a success only if an
ACK packet comes first. There is no such issue with the external one.
Do you need more information?
Could you capture DHCP packets with:

tcpdump -i enp0s25 -s 0 -w dhcp.pcap udp port 67 or port 68

when using dhclient and the failing internal client, and attach the
files? Or, if you prefer, attach the decoded text output:

tcpdump -vvenni enp0s25 udp port 67 or port 68

Thanks,
Beniamino
Vincent Lefevre
2019-08-09 15:10:01 UTC
Reply
Permalink
in the traces I see that there are 3 servers and one of them
advertises a subnet different from other two. This setup makes the
behavior non-deterministic because clients can get an address either
in the 10.0.1.0/24 or in the 140.77.12.0/23 network. Do you know if
the network configured in this way on purpose?
I think so, as there are 2 kinds of machines: those that are supposed
to have a fixed IP address on the main network, and the other machines,
which will be on a secondary network. My machine is in the former
class. I don't know how such machines are supposed to be identified
(probably with a weak identification), but I can see my machine
name in the DHCP Discover and DHCP Request packets.
12:29:03.690421 94:f1:28:19:08:00 > 98:90:96:bd:7f:f7, ethertype IPv4 (0x0800), length 366: (tos 0x0, ttl 63, id 55318, offset 0, flags [DF], proto UDP (17), length 352)
140.77.1.11.67 > 140.77.13.17.68: BOOTP/DHCP, Reply, length 324, hops 1, xid 0xff001675, secs 2, Flags [none]
Your-IP 140.77.13.17
Server-IP 140.77.14.50
Gateway-IP 140.77.12.1
Client-Ethernet-Address 98:90:96:bd:7f:f7
file "/lpxelinux.0"[|bootp]
to which the internal client replies with a request. Note the
12:29:03.690539 98:90:96:bd:7f:f7 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 340: (tos 0xc0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 326)
0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 98:90:96:bd:7f:f7, length 298, xid 0xff001675, secs 2, Flags [none]
Client-Ethernet-Address 98:90:96:bd:7f:f7
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Request
Client-ID Option 61, length 7: ether 98:90:96:bd:7f:f7
Subnet-Mask, Default-Gateway, Hostname, Domain-Name
Domain-Name-Server, Time-Zone, MTU, BR
Classless-Static-Route, Static-Route, YD, YS
NTP, Server-ID, Option 119, Classless-Static-Route-Microsoft
Option 252, RP
MSZ Option 57, length 2: 576
Server-ID Option 54, length 4: 140.77.1.11
Requested-IP Option 50, length 4: 140.77.13.17
Hostname Option 12, length 7: "cventin"
The DHCP server at 10.0.1.1 NAKs the request even if it had a
12:29:03.691585 5c:96:9d:6d:9d:48 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 342: (tos 0x10, ttl 128, id 0, offset 0, flags [none], proto UDP (17), length 328)
10.0.1.1.67 > 255.255.255.255.68: BOOTP/DHCP, Reply, length 300, xid 0xff001675, secs 2, Flags [Broadcast]
Server-IP 10.0.1.1
Client-Ethernet-Address 98:90:96:bd:7f:f7
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: NACK
Server-ID Option 54, length 4: 10.0.1.1
MSG Option 56, length 31: "requested address not available"
RFC 2131 says: "If a server receives a DHCPREQUEST message with an
invalid 'requested IP address', the server SHOULD respond to the
client with a DHCPNAK message and may choose to report the problem
to the system administrator."

So this seems correct. Note that it does not say that the server must
check the server-id, and the fact that it says "a server" instead of
"the server" tends to make me think that this is how it works.

BTW, if the server implicitly needs to check the server-id, why
doesn't the internal client do this too about the DHCPNAK response?
Also, RFC 2131 says that the "If the client receives a DHCPNAK
message, the client restarts the configuration process", that is what
the internal client does, until the ACK comes before or until
timeout. dhclient apparently ignores the NAK, but I haven't found yet
in the code where this is done and based on what.
It seems that RFC 2131 has some contradictions in case of several
DHCP servers on several networks. IMHO, the client should be
tolerant and ignore DHCPNAK if the server-id is different.
--
Vincent Lefèvre <***@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)
Beniamino Galvani
2019-08-12 07:50:01 UTC
Reply
Permalink
Post by Vincent Lefevre
in the traces I see that there are 3 servers and one of them
advertises a subnet different from other two. This setup makes the
behavior non-deterministic because clients can get an address either
in the 10.0.1.0/24 or in the 140.77.12.0/23 network. Do you know if
the network configured in this way on purpose?
I think so, as there are 2 kinds of machines: those that are supposed
to have a fixed IP address on the main network, and the other machines,
which will be on a secondary network. My machine is in the former
class. I don't know how such machines are supposed to be identified
(probably with a weak identification), but I can see my machine
name in the DHCP Discover and DHCP Request packets.
Ok, then this mechanism is not working since your machine is receiving
offers for both networks and randomly takes one. I don't know how
common this setup is, but the RFC seems to warn against it:

Once the network address and lease have been determined, the server
constructs a DHCPOFFER message with the offered configuration
parameters. It is important for all DHCP servers to return the same
parameters (with the possible exception of a newly allocated network
address) to ensure predictable client behavior regardless of which
server the client selects.
Post by Vincent Lefevre
[...]
to which the internal client replies with a request. Note the
[...]
The DHCP server at 10.0.1.1 NAKs the request even if it had a
[...]
RFC 2131 says: "If a server receives a DHCPREQUEST message with an
invalid 'requested IP address', the server SHOULD respond to the
client with a DHCPNAK message and may choose to report the problem
to the system administrator."
So this seems correct. Note that it does not say that the server must
check the server-id, and the fact that it says "a server" instead of
"the server" tends to make me think that this is how it works.
BTW, if the server implicitly needs to check the server-id, why
doesn't the internal client do this too about the DHCPNAK response?
This part of RFC 2131 is quite clear in my opinion:

3. The client receives one or more DHCPOFFER messages from one or more
servers. The client may choose to wait for multiple responses.
The client chooses one server from which to request configuration
parameters, based on the configuration parameters offered in the
DHCPOFFER messages. The client broadcasts a DHCPREQUEST message
that MUST include the 'server identifier' option to indicate which
server it has selected, and that MAY include other options
specifying desired configuration values. [...]

4. The servers receive the DHCPREQUEST broadcast from the client.
Those servers not selected by the DHCPREQUEST message use the
message as notification that the client has declined that server's
offer. The server selected in the DHCPREQUEST message commits the
binding for the client to persistent storage and responds with a
DHCPACK message containing the configuration parameters for the
requesting client. [...]

So the behavior of server 10.0.1.1 seems not compliant to RFC.
Post by Vincent Lefevre
Also, RFC 2131 says that the "If the client receives a DHCPNAK
message, the client restarts the configuration process", that is what
the internal client does, until the ACK comes before or until
timeout. dhclient apparently ignores the NAK, but I haven't found yet
in the code where this is done and based on what.
It seems that RFC 2131 has some contradictions in case of several
DHCP servers on several networks. IMHO, the client should be
tolerant and ignore DHCPNAK if the server-id is different.
I checked again and the internal client doesn't do any filtering based
on the server-id. In the dhclient log at:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=933930#42

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

the transaction succeeds because the ACK comes before any NAK, which
is the same thing it happens when the transaction succeeds with the
internal client. Perhaps could you capture other logs with dhclient
too see how it handles multiple NAK?

Thank you

Beniamino
Vincent Lefevre
2019-08-12 09:10:01 UTC
Reply
Permalink
Post by Beniamino Galvani
Post by Vincent Lefevre
in the traces I see that there are 3 servers and one of them
advertises a subnet different from other two. This setup makes the
behavior non-deterministic because clients can get an address either
in the 10.0.1.0/24 or in the 140.77.12.0/23 network. Do you know if
the network configured in this way on purpose?
I think so, as there are 2 kinds of machines: those that are supposed
to have a fixed IP address on the main network, and the other machines,
which will be on a secondary network. My machine is in the former
class. I don't know how such machines are supposed to be identified
(probably with a weak identification), but I can see my machine
name in the DHCP Discover and DHCP Request packets.
Ok, then this mechanism is not working since your machine is receiving
offers for both networks and randomly takes one. I don't know how
Once the network address and lease have been determined, the server
constructs a DHCPOFFER message with the offered configuration
parameters. It is important for all DHCP servers to return the same
parameters (with the possible exception of a newly allocated network
address) to ensure predictable client behavior regardless of which
server the client selects.
For machines with a static IP address that could be proposed to the
DHCP servers, this should not be an issue. This seems possible to do
with dhclient, but I suspect that users never do that in practice,
even we know our static address (it is given by the admin). So,
indeed, I suspect that there could be an issue with this configuration
in practice.

I'll ask the admins whether this configuration is expected (I can
see an advantage that this allows machines of the former class to
switch to the alternate network when there is an issue with the
main network, but I don't think that this is a good idea anyway,
because this can make machines indefinitely unreachable after a
temporary failure with the main DHCP servers).

BTW, I can see in the logs, that I never got a DHCPNAK before July 22.
So, it seems that something has changed. But I think that no-one
except me noticed, because I'm probably the first one to have upgraded
to the new NetworkManager versions.
Post by Beniamino Galvani
Post by Vincent Lefevre
It seems that RFC 2131 has some contradictions in case of several
DHCP servers on several networks. IMHO, the client should be
tolerant and ignore DHCPNAK if the server-id is different.
I checked again and the internal client doesn't do any filtering based
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=933930#42
[...]
Post by Beniamino Galvani
the transaction succeeds because the ACK comes before any NAK, which
is the same thing it happens when the transaction succeeds with the
internal client. Perhaps could you capture other logs with dhclient
too see how it handles multiple NAK?
Please look at the capture I had sent at

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=933930#74

i.e.

https://bugs.debian.org/cgi-bin/bugreport.cgi?att=1;bug=933930;filename=dhcp-dhclient.pcap;msg=74

The NAK comes first.
--
Vincent Lefèvre <***@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)
Loading...